-- Logs begin at Fri 2025-04-18 19:36:45 -03, end at Tue 2025-04-29 11:27:35 -03. -- Apr 29 11:26:04 volumio go-librespot[4816]: time="2025-04-29T11:26:04-03:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:5zwwW9Oq7ubSxoCGyW1nbY" Apr 29 11:26:08 volumio go-librespot[4816]: time="2025-04-29T11:26:08-03:00" level=trace msg="sent dealer ping" Apr 29 11:26:08 volumio go-librespot[4816]: time="2025-04-29T11:26:08-03:00" level=trace msg="received dealer pong" Apr 29 11:26:10 volumio go-librespot[4816]: time="2025-04-29T11:26:10-03:00" level=trace msg="received accesspoint ping" Apr 29 11:26:10 volumio go-librespot[4816]: time="2025-04-29T11:26:10-03:00" level=trace msg="received accesspoint pong ack" Apr 29 11:26:17 volumio go-librespot[4816]: time="2025-04-29T11:26:17-03:00" level=debug msg="fetched chunk 5/15, size: 524288" uri="spotify:track:5zwwW9Oq7ubSxoCGyW1nbY" Apr 29 11:26:29 volumio go-librespot[4816]: time="2025-04-29T11:26:29-03:00" level=debug msg="fetched chunk 6/15, size: 524288" uri="spotify:track:5zwwW9Oq7ubSxoCGyW1nbY" Apr 29 11:26:38 volumio go-librespot[4816]: time="2025-04-29T11:26:38-03:00" level=trace msg="sent dealer ping" Apr 29 11:26:38 volumio go-librespot[4816]: time="2025-04-29T11:26:38-03:00" level=trace msg="received dealer pong" Apr 29 11:26:42 volumio go-librespot[4816]: time="2025-04-29T11:26:42-03:00" level=debug msg="fetched chunk 7/15, size: 524288" uri="spotify:track:5zwwW9Oq7ubSxoCGyW1nbY" Apr 29 11:26:53 volumio go-librespot[4816]: time="2025-04-29T11:26:53-03:00" level=debug msg="fetched chunk 8/15, size: 524288" uri="spotify:track:5zwwW9Oq7ubSxoCGyW1nbY" Apr 29 11:27:05 volumio go-librespot[4816]: time="2025-04-29T11:27:05-03:00" level=debug msg="fetched chunk 9/15, size: 524288" uri="spotify:track:5zwwW9Oq7ubSxoCGyW1nbY" Apr 29 11:27:08 volumio go-librespot[4816]: time="2025-04-29T11:27:08-03:00" level=trace msg="sent dealer ping" Apr 29 11:27:08 volumio go-librespot[4816]: time="2025-04-29T11:27:08-03:00" level=trace msg="received dealer pong" Apr 29 11:27:16 volumio go-librespot[4816]: time="2025-04-29T11:27:16-03:00" level=debug msg="fetched chunk 10/15, size: 524288" uri="spotify:track:5zwwW9Oq7ubSxoCGyW1nbY" Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 0 Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::serviceStop Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 0 Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::serviceStop Apr 29 11:27:23 volumio volumio[1181]: info: Spotify Stop Apr 29 11:27:23 volumio volumio[1181]: SPOTIFY: SPOTIFY STOP Apr 29 11:27:23 volumio volumio[1181]: SPOTIFY: {"status":"play","position":0,"title":"Pink Venom","artist":"BLACKPINK","album":"BORN PINK","albumart":"https://i.scdn.co/image/ab67616d0000b273002ef53878df1b4e91c15406","uri":"spotify:track:5zwwW9Oq7ubSxoCGyW1nbY","trackType":"spotify","codec":"ogg","seek":1000,"duration":186,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":true,"repeat":null,"repeatSingle":false,"consume":false,"volume":"","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command to local API: /player/pause Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:23 volumio go-librespot[4816]: time="2025-04-29T11:27:23-03:00" level=debug msg="pause track at 91135ms" Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843645] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843671] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: touch_display: Setting screensaver timeout to 360 seconds. Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843711] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843716] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843725] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843750] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843775] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843797] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843818] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843865] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843899] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio go-librespot[4816]: time="2025-04-29T11:27:23-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843946] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:23 volumio volumio[1181]: info: [1745936843982] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:23 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:23 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:23 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844037] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=trace msg="emitting websocket event: paused" Apr 29 11:27:24 volumio volumio[1181]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5zwwW9Oq7ubSxoCGyW1nbY","play_origin":"go-librespot"}} Apr 29 11:27:24 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:24 volumio volumio[1181]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:24 volumio volumio[1181]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:24 volumio volumio[1181]: verbose: CURRENT POSITION 8 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::syncState stateService pause Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844097] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844166] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="resolved context of track" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844243] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844287] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844344] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844363] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844398] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:24 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:13MF2TYuyfITClL1R2ei6e","play_origin":"go-librespot"}} Apr 29 11:27:24 volumio volumio[1181]: info: camilladsp spawned new process with pid 11196, instance 1, run: true Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844518] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844558] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="selected format OGG_VORBIS_320 (4c0391fe981745fddf3b52093052917a42548062)" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="requested aes key for file 4c0391fe981745fddf3b52093052917a42548062, gid: 13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844768] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844802] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844827] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844845] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:24 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:24 volumio volumio[1181]: info: [1745936844890] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:24 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:24 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:24 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="fetched first chunk of 19, total size is 9908612 bytes" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - ---- read samplerate from file: 44100 Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=info msg="loaded track \"BOOMBAYAH\" (paused: false, position: 0ms, duration: 240793ms, prefetched: false)" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - Effects disabled Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - ---- read samplerate from file: 44100 Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - Effects disabled Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 29 11:27:24 volumio volumio[1181]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:24 volumio go-librespot[4816]: time="2025-04-29T11:27:24-03:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=trace msg="scheduling prefetch in 210s" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=trace msg="emitting websocket event: metadata" Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:13MF2TYuyfITClL1R2ei6e","name":"BOOMBAYAH","artist_names":["BLACKPINK"],"album_name":"SQUARE ONE","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ff4ec21d7817138cabcc19bc","position":0,"duration":240793,"release_date":"year:2016 month:8 day:8","track_number":2,"disc_number":1}} Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=trace msg="emitting websocket event: playing" Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:13MF2TYuyfITClL1R2ei6e","play_origin":"go-librespot"}} Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: {"status":"play","service":"spop","title":"BOOMBAYAH","artist":"BLACKPINK","album":"SQUARE ONE","albumart":"https://i.scdn.co/image/ab67616d00001e02ff4ec21d7817138cabcc19bc","uri":"spotify:track:13MF2TYuyfITClL1R2ei6e","trackType":"spotify","seek":0,"duration":240,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:25 volumio volumio[1181]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"BOOMBAYAH","artist":"BLACKPINK","album":"SQUARE ONE","albumart":"https://i.scdn.co/image/ab67616d00001e02ff4ec21d7817138cabcc19bc","uri":"spotify:track:13MF2TYuyfITClL1R2ei6e","trackType":"spotify","seek":0,"duration":240,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:25 volumio volumio[1181]: verbose: CURRENT POSITION 1 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::syncState stateService play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::serviceStop Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::serviceStop Apr 29 11:27:25 volumio volumio[1181]: info: Spotify Stop Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: SPOTIFY STOP Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: {"status":"stop","position":8,"title":"Pretty Savage","artist":"BLACKPINK","album":"THE ALBUM","albumart":"https://i.scdn.co/image/ab67616d0000b2737dd8f95320e8ef08aa121dfe","uri":"spotify:track:1XnpzbOGptRwfJhZgLbmSr","trackType":"spotify","codec":"ogg","seek":30,"duration":201,"samplerate":"320 kbps","bitdepth":"16 bit","random":true,"repeat":null,"repeatSingle":false,"consume":false,"volume":"","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command to local API: /player/pause Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845344] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=debug msg="resolved context of track" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:25 volumio volumio[1181]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:25 volumio volumio[1181]: verbose: CURRENT POSITION 9 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::syncState stateService stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:25 volumio volumio[1181]: info: No code Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845611] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7gRFDGEzF9UkBV233yv2dc","play_origin":"go-librespot"}} Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845630] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845671] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845715] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845752] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=debug msg="selected format OGG_VORBIS_320 (09715cbf05d480a71ae69609f28dbc1508d92571)" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:25 volumio go-librespot[4816]: time="2025-04-29T11:27:25-03:00" level=debug msg="requested aes key for file 09715cbf05d480a71ae69609f28dbc1508d92571, gid: 7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845782] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845816] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845869] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845903] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845945] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:25 volumio volumio[1181]: info: [1745936845984] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:25 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:25 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:25 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846037] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="fetched first chunk of 14, total size is 7055592 bytes" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846139] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=info msg="loaded track \"Shut Down\" (paused: false, position: 0ms, duration: 175889ms, prefetched: false)" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846204] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:7gRFDGEzF9UkBV233yv2dc" Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846274] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=trace msg="scheduling prefetch in 146s" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=trace msg="emitting websocket event: metadata" Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7gRFDGEzF9UkBV233yv2dc","name":"Shut Down","artist_names":["BLACKPINK"],"album_name":"BORN PINK","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02002ef53878df1b4e91c15406","position":0,"duration":175889,"release_date":"year:2022 month:9 day:15","track_number":2,"disc_number":1}} Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846329] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=trace msg="emitting websocket event: playing" Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7gRFDGEzF9UkBV233yv2dc","play_origin":"go-librespot"}} Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 0 Apr 29 11:27:26 volumio volumio[1181]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:26 volumio volumio[1181]: verbose: CURRENT POSITION 0 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::syncState stateService play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 0 Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::serviceStop Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 0 Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::serviceStop Apr 29 11:27:26 volumio volumio[1181]: info: Spotify Stop Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: SPOTIFY STOP Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: {"status":"stop","position":9,"title":"Typa Girl","artist":"BLACKPINK","album":"BORN PINK","albumart":"https://i.scdn.co/image/ab67616d0000b2734aeaaeeb0755f1d8a8b51738","uri":"spotify:track:0L8LOav65XwLjCLS11gNPD","trackType":"spotify","codec":"ogg","seek":231,"duration":179,"samplerate":"320 kbps","bitdepth":"16 bit","random":true,"repeat":null,"repeatSingle":false,"consume":false,"volume":"","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command to local API: /player/pause Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846585] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="resolved context of track" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:26 volumio volumio[1181]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:26 volumio volumio[1181]: verbose: CURRENT POSITION 4 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::syncState stateService stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:26 volumio volumio[1181]: info: No code Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846819] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:26 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6hvczQ05jc1yGlp9zhb95V","play_origin":"go-librespot"}} Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846851] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846884] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846925] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:26 volumio volumio[1181]: info: [1745936846969] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:26 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:26 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:26 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="selected format OGG_VORBIS_320 (a88b628bde6be852f01d77db467582296417308c)" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:26 volumio go-librespot[4816]: time="2025-04-29T11:27:26-03:00" level=debug msg="requested aes key for file a88b628bde6be852f01d77db467582296417308c, gid: 6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847006] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847037] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847069] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847184] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847241] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847280] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847303] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=debug msg="fetched first chunk of 15, total size is 7400256 bytes" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=info msg="loaded track \"Kill This Love\" (paused: false, position: 0ms, duration: 191050ms, prefetched: false)" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847381] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:6hvczQ05jc1yGlp9zhb95V" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=trace msg="scheduling prefetch in 161s" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=trace msg="emitting websocket event: metadata" Apr 29 11:27:27 volumio volumio[1181]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6hvczQ05jc1yGlp9zhb95V","name":"Kill This Love","artist_names":["BLACKPINK"],"album_name":"KILL THIS LOVE","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e20e5c366b497518353497b0","position":0,"duration":191050,"release_date":"year:2019 month:4 day:5","track_number":1,"disc_number":1}} Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847704] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=trace msg="emitting websocket event: playing" Apr 29 11:27:27 volumio volumio[1181]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6hvczQ05jc1yGlp9zhb95V","play_origin":"go-librespot"}} Apr 29 11:27:27 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:27 volumio volumio[1181]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:27 volumio volumio[1181]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:27 volumio volumio[1181]: verbose: CURRENT POSITION 7 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::syncState stateService play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::serviceStop Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::serviceStop Apr 29 11:27:27 volumio volumio[1181]: info: Spotify Stop Apr 29 11:27:27 volumio volumio[1181]: SPOTIFY: SPOTIFY STOP Apr 29 11:27:27 volumio volumio[1181]: SPOTIFY: {"status":"stop","position":4,"title":"As If It's Your Last","artist":"BLACKPINK","album":"As If It's Your Last","albumart":"https://i.scdn.co/image/ab67616d0000b273ac93d8b1bd84fa6b5291ba21","uri":"spotify:track:4ZxOuNHhpyOj4gv52MtQpT","trackType":"spotify","codec":"ogg","seek":205,"duration":213,"samplerate":"320 kbps","bitdepth":"16 bit","random":true,"repeat":null,"repeatSingle":false,"consume":false,"volume":"","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command to local API: /player/pause Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847818] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847863] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=debug msg="resolved context of track" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:27 volumio go-librespot[4816]: time="2025-04-29T11:27:27-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847918] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:27 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:27 volumio volumio[1181]: info: [1745936847988] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:27 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:27 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:27 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:28 volumio volumio[1181]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:28 volumio volumio[1181]: verbose: CURRENT POSITION 7 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::syncState stateService stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:28 volumio volumio[1181]: info: No code Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4Ws314Ylb27BVsvlZOy30C","play_origin":"go-librespot"}} Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="selected format OGG_VORBIS_320 (9d5e0fb7f4b730154c2f1d84ec0b0a329962cc85)" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="requested aes key for file 9d5e0fb7f4b730154c2f1d84ec0b0a329962cc85, gid: 4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848372] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848413] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848450] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848486] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848518] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="fetched first chunk of 15, total size is 7593332 bytes" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848542] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=info msg="loaded track \"Lovesick Girls\" (paused: false, position: 1ms, duration: 194765ms, prefetched: false)" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848572] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848598] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:4Ws314Ylb27BVsvlZOy30C" Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=trace msg="scheduling prefetch in 165s" Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=trace msg="emitting websocket event: metadata" Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4Ws314Ylb27BVsvlZOy30C","name":"Lovesick Girls","artist_names":["BLACKPINK"],"album_name":"THE ALBUM","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027dd8f95320e8ef08aa121dfe","position":1,"duration":194765,"release_date":"year:2020 month:10 day:2","track_number":5,"disc_number":1}} Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848892] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:28 volumio go-librespot[4816]: time="2025-04-29T11:27:28-03:00" level=trace msg="emitting websocket event: playing" Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4Ws314Ylb27BVsvlZOy30C","play_origin":"go-librespot"}} Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:28 volumio volumio[1181]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:28 volumio volumio[1181]: verbose: CURRENT POSITION 1 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::syncState stateService play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::stPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::serviceStop Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:28 volumio volumio[1181]: info: CoreCommandRouter::serviceStop Apr 29 11:27:28 volumio volumio[1181]: info: Spotify Stop Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: SPOTIFY STOP Apr 29 11:27:28 volumio volumio[1181]: SPOTIFY: {"status":"stop","position":7,"title":"BOOMBAYAH","artist":"BLACKPINK","album":"SQUARE ONE","albumart":"https://i.scdn.co/image/ab67616d0000b273ff4ec21d7817138cabcc19bc","uri":"spotify:track:13MF2TYuyfITClL1R2ei6e","trackType":"spotify","codec":"ogg","seek":29,"duration":240,"samplerate":"320 kbps","bitdepth":"16 bit","random":true,"repeat":null,"repeatSingle":false,"consume":false,"volume":"","dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command to local API: /player/pause Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:28 volumio volumio[1181]: info: [1745936848956] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:28 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:28 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:28 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:29 volumio volumio[1181]: info: [1745936849000] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:29 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=debug msg="resolved context of track" uri="spotify:track:1XnpzbOGptRwfJhZgLbmSr" Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1XnpzbOGptRwfJhZgLbmSr" Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1XnpzbOGptRwfJhZgLbmSr" Apr 29 11:27:29 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:29 volumio volumio[1181]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:29 volumio volumio[1181]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:29 volumio volumio[1181]: verbose: CURRENT POSITION 7 Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::syncState stateService stop Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:29 volumio volumio[1181]: info: No code Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::serviceClearAddPlay Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::serviceClearAddPlayTracks Apr 29 11:27:29 volumio volumio[1181]: error: WARNING: No clearAddPlayTracks method for service spop Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:29 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1XnpzbOGptRwfJhZgLbmSr","play_origin":"go-librespot"}} Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::serviceClearAddPlay Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::serviceClearAddPlayTracks Apr 29 11:27:29 volumio volumio[1181]: error: WARNING: No clearAddPlayTracks method for service spop Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::serviceClearAddPlay Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::serviceClearAddPlayTracks Apr 29 11:27:29 volumio volumio[1181]: error: WARNING: No clearAddPlayTracks method for service spop Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=debug msg="selected format OGG_VORBIS_320 (9eac8737ee18ff4d80a9fc34d746b899c8fa42b9)" uri="spotify:track:1XnpzbOGptRwfJhZgLbmSr" Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=debug msg="requested aes key for file 9eac8737ee18ff4d80a9fc34d746b899c8fa42b9, gid: 1XnpzbOGptRwfJhZgLbmSr" Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::serviceClearAddPlay Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::serviceClearAddPlayTracks Apr 29 11:27:29 volumio volumio[1181]: error: WARNING: No clearAddPlayTracks method for service spop Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1XnpzbOGptRwfJhZgLbmSr: failed retrieving audio key: failed retrieving aes key with code 2" Apr 29 11:27:29 volumio volumio[1181]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:29 volumio volumio[1181]: info: CoreStateMachine::serviceClearAddPlay Apr 29 11:27:29 volumio volumio[1181]: info: CoreCommandRouter::serviceClearAddPlayTracks Apr 29 11:27:29 volumio volumio[1181]: error: WARNING: No clearAddPlayTracks method for service spop Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=debug msg="resolved context of track" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:29 volumio go-librespot[4816]: time="2025-04-29T11:27:29-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:29 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4ZxOuNHhpyOj4gv52MtQpT","play_origin":"go-librespot"}} Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="selected format OGG_VORBIS_320 (61b3696bd271a5fbe50bece5590ac1903efa63d5)" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="requested aes key for file 61b3696bd271a5fbe50bece5590ac1903efa63d5, gid: 4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="fetched first chunk of 17, total size is 8629992 bytes" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=info msg="loaded track \"As If It's Your Last\" (paused: false, position: 0ms, duration: 213264ms, prefetched: false)" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:4ZxOuNHhpyOj4gv52MtQpT" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=trace msg="scheduling prefetch in 183s" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=trace msg="emitting websocket event: metadata" Apr 29 11:27:30 volumio volumio[1181]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4ZxOuNHhpyOj4gv52MtQpT","name":"As If It's Your Last","artist_names":["BLACKPINK"],"album_name":"As If It's Your Last","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ac93d8b1bd84fa6b5291ba21","position":0,"duration":213264,"release_date":"year:2017 month:6 day:22","track_number":1,"disc_number":1}} Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=trace msg="emitting websocket event: playing" Apr 29 11:27:30 volumio volumio[1181]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4ZxOuNHhpyOj4gv52MtQpT","play_origin":"go-librespot"}} Apr 29 11:27:30 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:30 volumio volumio[1181]: SPOTIFY: {"status":"play","service":"spop","title":"As If It's Your Last","artist":"BLACKPINK","album":"As If It's Your Last","albumart":"https://i.scdn.co/image/ab67616d00001e02ac93d8b1bd84fa6b5291ba21","uri":"spotify:track:4ZxOuNHhpyOj4gv52MtQpT","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:30 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:30 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:30 volumio volumio[1181]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"As If It's Your Last","artist":"BLACKPINK","album":"As If It's Your Last","albumart":"https://i.scdn.co/image/ab67616d00001e02ac93d8b1bd84fa6b5291ba21","uri":"spotify:track:4ZxOuNHhpyOj4gv52MtQpT","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:30 volumio volumio[1181]: verbose: CURRENT POSITION 10 Apr 29 11:27:30 volumio volumio[1181]: info: CoreStateMachine::syncState stateService play Apr 29 11:27:30 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="resolved context of track" uri="spotify:track:4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:30 volumio go-librespot[4816]: time="2025-04-29T11:27:30-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:31 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:31 volumio volumio[1181]: SPOTIFY: {"status":"play","service":"spop","title":"As If It's Your Last","artist":"BLACKPINK","album":"As If It's Your Last","albumart":"https://i.scdn.co/image/ab67616d00001e02ac93d8b1bd84fa6b5291ba21","uri":"spotify:track:4ZxOuNHhpyOj4gv52MtQpT","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:31 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:31 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:31 volumio volumio[1181]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"As If It's Your Last","artist":"BLACKPINK","album":"As If It's Your Last","albumart":"https://i.scdn.co/image/ab67616d00001e02ac93d8b1bd84fa6b5291ba21","uri":"spotify:track:4ZxOuNHhpyOj4gv52MtQpT","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:31 volumio volumio[1181]: verbose: CURRENT POSITION 10 Apr 29 11:27:31 volumio volumio[1181]: info: CoreStateMachine::syncState stateService play Apr 29 11:27:31 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus play Apr 29 11:27:31 volumio volumio[1181]: info: Received an update from plugin. extracting info from payload Apr 29 11:27:31 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:31 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:31 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:31 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:31 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:31 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:31 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:31 volumio go-librespot[4816]: time="2025-04-29T11:27:31-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:31 volumio go-librespot[4816]: time="2025-04-29T11:27:31-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:31 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4SFknyjLcyTLJFPKD2m96o","play_origin":"go-librespot"}} Apr 29 11:27:31 volumio go-librespot[4816]: time="2025-04-29T11:27:31-03:00" level=debug msg="selected format OGG_VORBIS_320 (d2bb970496aca69817264833b74619731cf44fb3)" uri="spotify:track:4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:31 volumio go-librespot[4816]: time="2025-04-29T11:27:31-03:00" level=debug msg="requested aes key for file d2bb970496aca69817264833b74619731cf44fb3, gid: 4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:31 volumio go-librespot[4816]: time="2025-04-29T11:27:31-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4SFknyjLcyTLJFPKD2m96o: failed retrieving audio key: failed retrieving aes key with code 2" Apr 29 11:27:31 volumio volumio[1181]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Apr 29 11:27:31 volumio go-librespot[4816]: time="2025-04-29T11:27:31-03:00" level=debug msg="resolved context of track" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:31 volumio go-librespot[4816]: time="2025-04-29T11:27:31-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:31 volumio go-librespot[4816]: time="2025-04-29T11:27:31-03:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:32 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4lQsB3ERTWSNaAN1IkuNRl","play_origin":"go-librespot"}} Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="selected format OGG_VORBIS_320 (f5b88e0e182bf167108a64504ad87b7bc86d7408)" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="requested aes key for file f5b88e0e182bf167108a64504ad87b7bc86d7408, gid: 4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="fetched first chunk of 16, total size is 8201728 bytes" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=info msg="loaded track \"DDU-DU DDU-DU\" (paused: false, position: 1ms, duration: 211350ms, prefetched: false)" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:4lQsB3ERTWSNaAN1IkuNRl" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=trace msg="scheduling prefetch in 181s" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=trace msg="emitting websocket event: metadata" Apr 29 11:27:32 volumio volumio[1181]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4lQsB3ERTWSNaAN1IkuNRl","name":"DDU-DU DDU-DU","artist_names":["BLACKPINK"],"album_name":"SQUARE UP","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02bfd46639322b597331d9ecef","position":1,"duration":211350,"release_date":"year:2018 month:6 day:15","track_number":1,"disc_number":1}} Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="resolved context of track" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:32 volumio go-librespot[4816]: time="2025-04-29T11:27:32-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:33 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0L8LOav65XwLjCLS11gNPD","play_origin":"go-librespot"}} Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="selected format OGG_VORBIS_320 (bf877976b50e942c993dbba99727b874c7c0a984)" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="requested aes key for file bf877976b50e942c993dbba99727b874c7c0a984, gid: 0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::stPlaybackTimer Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::serviceStop Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:33 volumio volumio[1181]: info: ControllerMpd::stop Apr 29 11:27:33 volumio volumio[1181]: verbose: ControllerMpd::sendMpdCommand stop Apr 29 11:27:33 volumio volumio[1181]: info: sendMpdCommand stop took 9 milliseconds Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 1 Apr 29 11:27:33 volumio volumio[1181]: info: [1745936853207] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:33 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 9 Apr 29 11:27:33 volumio volumio[1181]: info: [1745936853421] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:33 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="fetched first chunk of 15, total size is 7390340 bytes" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=info msg="loaded track \"Typa Girl\" (paused: false, position: 0ms, duration: 179172ms, prefetched: false)" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:0L8LOav65XwLjCLS11gNPD" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=trace msg="scheduling prefetch in 149s" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=trace msg="emitting websocket event: metadata" Apr 29 11:27:33 volumio volumio[1181]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0L8LOav65XwLjCLS11gNPD","name":"Typa Girl","artist_names":["BLACKPINK"],"album_name":"BORN PINK","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024aeaaeeb0755f1d8a8b51738","position":0,"duration":179172,"release_date":"year:2022 month:9 day:16","track_number":3,"disc_number":1}} Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 7 Apr 29 11:27:33 volumio volumio[1181]: info: [1745936853753] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:33 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 5 Apr 29 11:27:33 volumio volumio[1181]: info: [1745936853805] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:33 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:33 volumio volumio[1181]: info: [1745936853869] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:33 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:33 volumio go-librespot[4816]: time="2025-04-29T11:27:33-03:00" level=trace msg="emitting websocket event: playing" Apr 29 11:27:33 volumio volumio[1181]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0L8LOav65XwLjCLS11gNPD","play_origin":"go-librespot"}} Apr 29 11:27:33 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:33 volumio volumio[1181]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:33 volumio volumio[1181]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:33 volumio volumio[1181]: verbose: CURRENT POSITION 2 Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::syncState stateService play Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::stPlaybackTimer Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::serviceStop Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 2 Apr 29 11:27:33 volumio volumio[1181]: info: CoreCommandRouter::serviceStop Apr 29 11:27:33 volumio volumio[1181]: info: Spotify Stop Apr 29 11:27:33 volumio volumio[1181]: SPOTIFY: SPOTIFY STOP Apr 29 11:27:33 volumio volumio[1181]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":"","dbVolume":null,"mute":false,"disableVolumeControl":false,"random":true,"repeat":null,"repeatSingle":false,"consume":false} Apr 29 11:27:33 volumio volumio[1181]: info: Sending Spotify command to local API: /player/pause Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrack 4 Apr 29 11:27:33 volumio volumio[1181]: info: [1745936853952] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:33 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:33 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:33 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 8 Apr 29 11:27:34 volumio volumio[1181]: info: [1745936854008] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:34 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 3 Apr 29 11:27:34 volumio volumio[1181]: info: [1745936854058] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:34 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=debug msg="resolved context of track" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::startPlaybackTimer Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:34 volumio volumio[1181]: info: [1745936854136] ControllerSpotify::clearAddPlayTrack Apr 29 11:27:34 volumio volumio[1181]: info: Sending Spotify command with payload to local API: /player/play Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:34 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:34 volumio volumio[1181]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:34 volumio volumio[1181]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:34 volumio volumio[1181]: verbose: CURRENT POSITION 6 Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::syncState stateService stop Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:34 volumio volumio[1181]: info: No code Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::pushState Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 6 Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioPushState Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioNext Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::next Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::stop Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::play index undefined Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:34 volumio volumio[1181]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:13MF2TYuyfITClL1R2ei6e","play_origin":"go-librespot"}} Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::serviceClearAddPlay Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::serviceClearAddPlayTracks Apr 29 11:27:34 volumio volumio[1181]: error: WARNING: No clearAddPlayTracks method for service spop Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::serviceClearAddPlay Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::serviceClearAddPlayTracks Apr 29 11:27:34 volumio volumio[1181]: error: WARNING: No clearAddPlayTracks method for service spop Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=debug msg="selected format OGG_VORBIS_320 (4c0391fe981745fddf3b52093052917a42548062)" uri="spotify:track:13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=debug msg="requested aes key for file 4c0391fe981745fddf3b52093052917a42548062, gid: 13MF2TYuyfITClL1R2ei6e" Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::updateTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrackBlock Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::serviceClearAddPlay Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::serviceClearAddPlayTracks Apr 29 11:27:34 volumio volumio[1181]: error: WARNING: No clearAddPlayTracks method for service spop Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:13MF2TYuyfITClL1R2ei6e: failed retrieving audio key: failed retrieving aes key with code 2" Apr 29 11:27:34 volumio volumio[1181]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=trace msg="emitting websocket event: playing" Apr 29 11:27:34 volumio volumio[1181]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:13MF2TYuyfITClL1R2ei6e","play_origin":"go-librespot"}} Apr 29 11:27:34 volumio volumio[1181]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 11:27:34 volumio volumio[1181]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::servicePushState Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:34 volumio volumio[1181]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 11:27:34 volumio volumio[1181]: verbose: CURRENT POSITION 10 Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::syncState stateService play Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::syncState currentStatus stop Apr 29 11:27:34 volumio volumio[1181]: info: CoreCommandRouter::volumioPrevious Apr 29 11:27:34 volumio volumio[1181]: info: CoreStateMachine::previous Apr 29 11:27:34 volumio volumio[1181]: info: CorePlayQueue::getTrack 10 Apr 29 11:27:34 volumio volumio[1181]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 29 11:27:34 volumio volumio[1181]: TypeError: Cannot read property 'service' of undefined Apr 29 11:27:34 volumio volumio[1181]: at CoreStateMachine.previous (/volumio/app/statemachine.js:1325:97) Apr 29 11:27:34 volumio volumio[1181]: at CoreCommandRouter.volumioPrevious (/volumio/app/index.js:97:28) Apr 29 11:27:34 volumio volumio[1181]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:270:33) Apr 29 11:27:34 volumio volumio[1181]: at Socket.emit (events.js:315:20) Apr 29 11:27:34 volumio volumio[1181]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Apr 29 11:27:34 volumio volumio[1181]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Apr 29 11:27:34 volumio volumio[1181]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=debug msg="resolved context of track" uri="spotify:track:4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:34 volumio go-librespot[4816]: time="2025-04-29T11:27:34-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:35 volumio go-librespot[4816]: time="2025-04-29T11:27:35-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 11:27:35 volumio go-librespot[4816]: time="2025-04-29T11:27:35-03:00" level=trace msg="emitting websocket event: will_play" Apr 29 11:27:35 volumio sudo[11230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-29 11:26 Apr 29 11:27:35 volumio sudo[11230]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 29 11:27:35 volumio go-librespot[4816]: time="2025-04-29T11:27:35-03:00" level=debug msg="selected format OGG_VORBIS_320 (d2bb970496aca69817264833b74619731cf44fb3)" uri="spotify:track:4SFknyjLcyTLJFPKD2m96o" Apr 29 11:27:35 volumio go-librespot[4816]: time="2025-04-29T11:27:35-03:00" level=debug msg="requested aes key for file d2bb970496aca69817264833b74619731cf44fb3, gid: 4SFknyjLcyTLJFPKD2m96o" PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"