-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Thu 2025-05-01 20:54:19 CST. -- May 01 20:53:05 volumio go-librespot[1106]: time="2025-05-01T20:53:05+08:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio volumio[840]: info: Preload queue cleared May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::volumioReplaceandPlayItems May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::ClearQueue May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::stop May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::stPlaybackTimer May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:11 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:11 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::serviceStop May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::serviceStop May 01 20:53:11 volumio volumio[840]: info: Spotify Stop May 01 20:53:11 volumio volumio[840]: SPOTIFY: SPOTIFY STOP May 01 20:53:11 volumio volumio[840]: SPOTIFY: {"status":"play","position":2,"title":"What Are Words (feat. Peter Hollens & Evynne Hollens)","artist":"Lauren Christy","album":"What Are Words (feat. Peter Hollens & Evynne Hollens)","albumart":"https://i.scdn.co/image/ab67616d0000b27334690b458b8a661fa51f5e78","uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","trackType":"spotify","codec":"ogg","seek":0,"duration":218,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 01 20:53:11 volumio volumio[840]: info: Sending Spotify command to local API: /player/pause May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::clearPlayQueue May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::addQueueItems May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::addQueueItems May 01 20:53:11 volumio volumio[840]: info: Preload queue cleared May 01 20:53:11 volumio volumio[840]: info: Adding Item to queue: spotify:track:2qiOvWyHX28d8nrWTio3yV May 01 20:53:11 volumio volumio[840]: info: Using cached record of: spotify:track:2qiOvWyHX28d8nrWTio3yV May 01 20:53:11 volumio volumio[840]: info: Adding Item to queue: spotify:track:2JzZzZUQj3Qff7wapcbKjc May 01 20:53:11 volumio volumio[840]: info: Using cached record of: spotify:track:2JzZzZUQj3Qff7wapcbKjc May 01 20:53:11 volumio volumio[840]: info: Adding Item to queue: spotify:track:21pL95f63XT8Mezt8qPOtq May 01 20:53:11 volumio volumio[840]: info: Using cached record of: spotify:track:21pL95f63XT8Mezt8qPOtq May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::volumioPlay May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::play index 2 May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::addQueueItems May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::addQueueItems May 01 20:53:11 volumio volumio[840]: info: Preload queue cleared May 01 20:53:11 volumio volumio[840]: info: Adding Item to queue: spotify:track:0MoEgFObCeX0PuHj1R2JDK May 01 20:53:11 volumio volumio[840]: info: Using cached record of: spotify:track:0MoEgFObCeX0PuHj1R2JDK May 01 20:53:11 volumio volumio[840]: info: Adding Item to queue: spotify:track:1RbmQY9DbIy0RqWFs04FOX May 01 20:53:11 volumio volumio[840]: info: Using cached record of: spotify:track:1RbmQY9DbIy0RqWFs04FOX May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::stop May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::play index undefined May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:11 volumio volumio[840]: info: CoreStateMachine::startPlaybackTimer May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:11 volumio volumio[840]: info: [1746103991071] ControllerSpotify::clearAddPlayTrack May 01 20:53:11 volumio volumio[840]: info: Sending Spotify command with payload to local API: /player/play May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="resolved context of track" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=trace msg="emitting websocket event: will_play" May 01 20:53:11 volumio volumio[840]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","play_origin":"go-librespot"}} May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="selected format OGG_VORBIS_320 (c9fe9024372ff2d8b89113459ae77d74324f3800)" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="requested aes key for file c9fe9024372ff2d8b89113459ae77d74324f3800, gid: 21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="fetched first chunk of 15, total size is 7518988 bytes" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=info msg="loaded track \"What Are Words (feat. Peter Hollens & Evynne Hollens)\" (paused: false, position: 0ms, duration: 218000ms, prefetched: false)" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=trace msg="scheduling prefetch in 188s" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=trace msg="emitting websocket event: metadata" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="pause track at 12ms" May 01 20:53:11 volumio volumio[840]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","name":"What Are Words (feat. Peter Hollens \u0026 Evynne Hollens)","artist_names":["Lauren Christy","Rodney Jerkins","Andre Lindal","The Piano Guys","Peter Hollens","Evynne Hollens"],"album_name":"What Are Words (feat. Peter Hollens \u0026 Evynne Hollens)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0234690b458b8a661fa51f5e78","position":0,"duration":218000,"release_date":"year:2015 month:5 day:13","track_number":1,"disc_number":1}} May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:21pL95f63XT8Mezt8qPOtq" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:11 volumio go-librespot[1106]: time="2025-05-01T20:53:11+08:00" level=trace msg="emitting websocket event: playing" May 01 20:53:11 volumio volumio[840]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","play_origin":"go-librespot"}} May 01 20:53:11 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:11 volumio volumio[840]: SPOTIFY: {"status":"play","service":"spop","title":"What Are Words (feat. Peter Hollens & Evynne Hollens)","artist":"Lauren Christy, Rodney Jerkins, Andre Lindal, The Piano Guys, Peter Hollens, Evynne Hollens","album":"What Are Words (feat. Peter Hollens & Evynne Hollens)","albumart":"https://i.scdn.co/image/ab67616d00001e0234690b458b8a661fa51f5e78","uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","trackType":"spotify","seek":0,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:11 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:11 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:11 volumio volumio[840]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"What Are Words (feat. Peter Hollens & Evynne Hollens)","artist":"Lauren Christy, Rodney Jerkins, Andre Lindal, The Piano Guys, Peter Hollens, Evynne Hollens","album":"What Are Words (feat. Peter Hollens & Evynne Hollens)","albumart":"https://i.scdn.co/image/ab67616d00001e0234690b458b8a661fa51f5e78","uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","trackType":"spotify","seek":0,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:12 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:53:12 volumio volumio[840]: info: CoreStateMachine::syncState stateService play May 01 20:53:12 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus stop May 01 20:53:12 volumio go-librespot[1106]: time="2025-05-01T20:53:12+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:12 volumio go-librespot[1106]: time="2025-05-01T20:53:12+08:00" level=trace msg="emitting websocket event: paused" May 01 20:53:12 volumio volumio[840]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","play_origin":"go-librespot"}} May 01 20:53:12 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:12 volumio volumio[840]: SPOTIFY: {"status":"pause","service":"spop","title":"What Are Words (feat. Peter Hollens & Evynne Hollens)","artist":"Lauren Christy, Rodney Jerkins, Andre Lindal, The Piano Guys, Peter Hollens, Evynne Hollens","album":"What Are Words (feat. Peter Hollens & Evynne Hollens)","albumart":"https://i.scdn.co/image/ab67616d00001e0234690b458b8a661fa51f5e78","uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","trackType":"spotify","seek":0,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:12 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:12 volumio volumio[840]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"What Are Words (feat. Peter Hollens & Evynne Hollens)","artist":"Lauren Christy, Rodney Jerkins, Andre Lindal, The Piano Guys, Peter Hollens, Evynne Hollens","album":"What Are Words (feat. Peter Hollens & Evynne Hollens)","albumart":"https://i.scdn.co/image/ab67616d00001e0234690b458b8a661fa51f5e78","uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","trackType":"spotify","seek":0,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:12 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:53:12 volumio volumio[840]: info: CoreStateMachine::syncState stateService pause May 01 20:53:12 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus play May 01 20:53:12 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:12 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:12 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:12 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:12 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:12 volumio volumio[840]: SPOTIFY: {"status":"pause","service":"spop","title":"What Are Words (feat. Peter Hollens & Evynne Hollens)","artist":"Lauren Christy, Rodney Jerkins, Andre Lindal, The Piano Guys, Peter Hollens, Evynne Hollens","album":"What Are Words (feat. Peter Hollens & Evynne Hollens)","albumart":"https://i.scdn.co/image/ab67616d00001e0234690b458b8a661fa51f5e78","uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","trackType":"spotify","seek":0,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:12 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:12 volumio volumio[840]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"What Are Words (feat. Peter Hollens & Evynne Hollens)","artist":"Lauren Christy, Rodney Jerkins, Andre Lindal, The Piano Guys, Peter Hollens, Evynne Hollens","album":"What Are Words (feat. Peter Hollens & Evynne Hollens)","albumart":"https://i.scdn.co/image/ab67616d00001e0234690b458b8a661fa51f5e78","uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","trackType":"spotify","seek":0,"duration":218,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:12 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:53:12 volumio volumio[840]: info: CoreStateMachine::syncState stateService pause May 01 20:53:12 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus play May 01 20:53:12 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:12 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:12 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:12 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 01 20:53:12 volumio volumio[840]: info: Discovery: Getting this device information May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::volumioGetState May 01 20:53:12 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 01 20:53:14 volumio nmbd[752]: [2025/05/01 20:53:14.020142, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) May 01 20:53:14 volumio nmbd[752]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.40.190 for name WORKGROUP<1d>. May 01 20:53:14 volumio nmbd[752]: This response was from IP 192.168.40.85, reporting an IP address of 10.168.2.1. May 01 20:53:21 volumio go-librespot[1106]: time="2025-05-01T20:53:21+08:00" level=trace msg="sent dealer ping" May 01 20:53:21 volumio go-librespot[1106]: time="2025-05-01T20:53:21+08:00" level=trace msg="received dealer pong" May 01 20:53:22 volumio volumio[840]: info: CoreCommandRouter::volumioNext May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::next May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::stop May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::stPlaybackTimer May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:22 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:22 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:22 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:22 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:22 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:22 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::serviceStop May 01 20:53:22 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:22 volumio volumio[840]: info: CoreCommandRouter::serviceStop May 01 20:53:22 volumio volumio[840]: info: Spotify Stop May 01 20:53:22 volumio volumio[840]: SPOTIFY: SPOTIFY STOP May 01 20:53:22 volumio volumio[840]: SPOTIFY: {"status":"play","position":2,"title":"What Are Words (feat. Peter Hollens & Evynne Hollens)","artist":"Lauren Christy","album":"What Are Words (feat. Peter Hollens & Evynne Hollens)","albumart":"https://i.scdn.co/image/ab67616d0000b27334690b458b8a661fa51f5e78","uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","trackType":"spotify","codec":"ogg","seek":334,"duration":218,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 01 20:53:22 volumio volumio[840]: info: Sending Spotify command to local API: /player/pause May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::play index undefined May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:22 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::startPlaybackTimer May 01 20:53:22 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:22 volumio volumio[840]: info: [1746104002530] ControllerSpotify::clearAddPlayTrack May 01 20:53:22 volumio volumio[840]: info: Sending Spotify command with payload to local API: /player/play May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:22 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=debug msg="pause track at 756ms" May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=trace msg="emitting websocket event: paused" May 01 20:53:22 volumio volumio[840]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:21pL95f63XT8Mezt8qPOtq","play_origin":"go-librespot"}} May 01 20:53:22 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:22 volumio volumio[840]: 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} May 01 20:53:22 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:22 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:22 volumio volumio[840]: 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} May 01 20:53:22 volumio volumio[840]: verbose: CURRENT POSITION 3 May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::syncState stateService pause May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus stop May 01 20:53:22 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:22 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:22 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:22 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:22 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:22 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=debug msg="resolved context of track" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:22 volumio go-librespot[1106]: time="2025-05-01T20:53:22+08:00" level=trace msg="emitting websocket event: will_play" May 01 20:53:22 volumio volumio[840]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","play_origin":"go-librespot"}} May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=debug msg="selected format OGG_VORBIS_320 (78ee5d1f7efbd65e941aa45e8d3833ad091dfbb5)" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=debug msg="requested aes key for file 78ee5d1f7efbd65e941aa45e8d3833ad091dfbb5, gid: 0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=debug msg="fetched first chunk of 13, total size is 6646572 bytes" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08: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" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=info msg="loaded track \"What Are Words\" (paused: false, position: 0ms, duration: 189413ms, prefetched: false)" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:23 volumio kernel: bcm2835-i2s fe203000.i2s: I2S SYNC error! May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=debug msg="fetched chunk 3/12, size: 524288" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=debug msg="fetched chunk 1/12, size: 524288" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=trace msg="scheduling prefetch in 159s" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=trace msg="emitting websocket event: metadata" May 01 20:53:23 volumio volumio[840]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","name":"What Are Words","artist_names":["Alexander Hurtig"],"album_name":"What Are Words","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0288a562ccd5dabacfe1f7273c","position":0,"duration":189413,"release_date":"year:2011 month:4 day:5","track_number":1,"disc_number":1}} May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=debug msg="fetched chunk 2/12, size: 524288" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:23 volumio go-librespot[1106]: time="2025-05-01T20:53:23+08:00" level=trace msg="emitting websocket event: playing" May 01 20:53:23 volumio volumio[840]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","play_origin":"go-librespot"}} May 01 20:53:23 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:23 volumio volumio[840]: SPOTIFY: {"status":"play","service":"spop","title":"What Are Words","artist":"Alexander Hurtig","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e0288a562ccd5dabacfe1f7273c","uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","trackType":"spotify","seek":0,"duration":189,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:23 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:23 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:23 volumio volumio[840]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"What Are Words","artist":"Alexander Hurtig","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e0288a562ccd5dabacfe1f7273c","uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","trackType":"spotify","seek":0,"duration":189,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:23 volumio volumio[840]: verbose: CURRENT POSITION 3 May 01 20:53:23 volumio volumio[840]: info: CoreStateMachine::syncState stateService play May 01 20:53:23 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus stop May 01 20:53:23 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:23 volumio volumio[840]: SPOTIFY: {"status":"play","service":"spop","title":"What Are Words","artist":"Alexander Hurtig","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e0288a562ccd5dabacfe1f7273c","uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","trackType":"spotify","seek":0,"duration":189,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:23 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:23 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:23 volumio volumio[840]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"What Are Words","artist":"Alexander Hurtig","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e0288a562ccd5dabacfe1f7273c","uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","trackType":"spotify","seek":0,"duration":189,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:23 volumio volumio[840]: verbose: CURRENT POSITION 3 May 01 20:53:23 volumio volumio[840]: info: CoreStateMachine::syncState stateService play May 01 20:53:23 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus play May 01 20:53:23 volumio volumio[840]: info: Received an update from plugin. extracting info from payload May 01 20:53:23 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:23 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:23 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:23 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:23 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:23 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:23 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:23 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:23 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:23 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:23 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:32 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:32 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: spop , goto May 01 20:53:33 volumio volumio[840]: info: Executing endpoint getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: Executing endpoint getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: Executing endpoint getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: Executing endpoint getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: Executing endpoint getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 01 20:53:33 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:33 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:36 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:36 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:37 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:37 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:38 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:38 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:38 volumio go-librespot[1106]: time="2025-05-01T20:53:38+08:00" level=debug msg="fetched chunk 4/12, size: 524288" uri="spotify:track:0MoEgFObCeX0PuHj1R2JDK" May 01 20:53:38 volumio volumio[840]: error: Failed request for metavolumio API May 01 20:53:38 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:38 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:38 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:38 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:38 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:38 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:39 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:39 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:40 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:40 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:40 volumio volumio[840]: info: Executing endpoint metavolumio May 01 20:53:40 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 01 20:53:41 volumio volumio[840]: error: Failed request for metavolumio API May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 01 20:53:42 volumio volumio[840]: info: Discovery: Getting this device information May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioGetState May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 01 20:53:42 volumio volumio[840]: info: Preload queue cleared May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioReplaceandPlayItems May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::ClearQueue May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::stop May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::stPlaybackTimer May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:42 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:42 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::serviceStop May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrack 3 May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::serviceStop May 01 20:53:42 volumio volumio[840]: info: Spotify Stop May 01 20:53:42 volumio volumio[840]: SPOTIFY: SPOTIFY STOP May 01 20:53:42 volumio volumio[840]: SPOTIFY: {"status":"play","position":3,"title":"What Are Words","artist":"Alexander Hurtig","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d0000b27388a562ccd5dabacfe1f7273c","uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","trackType":"spotify","codec":"ogg","seek":0,"duration":189,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 01 20:53:42 volumio volumio[840]: info: Sending Spotify command to local API: /player/pause May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::clearPlayQueue May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::addQueueItems May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::addQueueItems May 01 20:53:42 volumio volumio[840]: info: Preload queue cleared May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:6iOGLZt4sf2esgvLIdc4iY May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:6iOGLZt4sf2esgvLIdc4iY in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:6iOGLZt4sf2esgvLIdc4iY May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=debug msg="pause track at 19024ms" May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","service":"spop","name":"Don’t Say Goodbye","artist":"Chris Medina","album":"What Are Words","type":"song","duration":226,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioPlay May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::play index 0 May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::addQueueItems May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::addQueueItems May 01 20:53:42 volumio volumio[840]: info: Preload queue cleared May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:5NxsPRiNuNwrKHpFtgAyBC May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:5NxsPRiNuNwrKHpFtgAyBC in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:5NxsPRiNuNwrKHpFtgAyBC May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:6uYiyQpKgwkWuoPEQinz67 May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:6uYiyQpKgwkWuoPEQinz67 in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:6uYiyQpKgwkWuoPEQinz67 May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:50A1WCxKycJUHRr4Rz6WrD May 01 20:53:42 volumio volumio[840]: info: Using cached record of: spotify:track:50A1WCxKycJUHRr4Rz6WrD May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:5wuY6MfARX31RSSwz6l9yN May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:5wuY6MfARX31RSSwz6l9yN in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:5wuY6MfARX31RSSwz6l9yN May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:0RAwnhNxm3zvYbSa7WiI8Q May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:0RAwnhNxm3zvYbSa7WiI8Q in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:0RAwnhNxm3zvYbSa7WiI8Q May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:5tE5hwlVj2M25ERfO2jpdw May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:5tE5hwlVj2M25ERfO2jpdw in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:5tE5hwlVj2M25ERfO2jpdw May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:6jhRNXGrN07GPK2Cr1VdDZ May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:6jhRNXGrN07GPK2Cr1VdDZ in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:6jhRNXGrN07GPK2Cr1VdDZ May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:4p2qQO38X1Ao3viaKeNYgv May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:4p2qQO38X1Ao3viaKeNYgv in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:4p2qQO38X1Ao3viaKeNYgv May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:2e8BRFuh2qXXS5btl3Zf7o May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:2e8BRFuh2qXXS5btl3Zf7o in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:2e8BRFuh2qXXS5btl3Zf7o May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:1IPZCwilyEi0Fqg3WWUtTN May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:1IPZCwilyEi0Fqg3WWUtTN in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:1IPZCwilyEi0Fqg3WWUtTN May 01 20:53:42 volumio volumio[840]: info: Adding Item to queue: spotify:track:4pv7hzN61NksevP7nRVNHv May 01 20:53:42 volumio volumio[840]: info: Exploding uri spotify:track:4pv7hzN61NksevP7nRVNHv in service spop May 01 20:53:42 volumio volumio[840]: SPOTIFY: EXPLODING URI:spotify:track:4pv7hzN61NksevP7nRVNHv May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::stop May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::play index undefined May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::startPlaybackTimer May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioGetVisibleSources May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 01 20:53:42 volumio volumio[840]: info: [1746104022626] ControllerSpotify::clearAddPlayTrack May 01 20:53:42 volumio volumio[840]: info: Sending Spotify command with payload to local API: /player/play May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=trace msg="emitting websocket event: paused" May 01 20:53:42 volumio volumio[840]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0MoEgFObCeX0PuHj1R2JDK","play_origin":"go-librespot"}} May 01 20:53:42 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:42 volumio volumio[840]: 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} May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:42 volumio volumio[840]: 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} May 01 20:53:42 volumio volumio[840]: verbose: CURRENT POSITION 0 May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::syncState stateService pause May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus stop May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:42 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:42 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=debug msg="resolved context of track" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5NxsPRiNuNwrKHpFtgAyBC","service":"spop","name":"One More Time","artist":"Chris Medina","album":"What Are Words","type":"song","duration":244,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5wuY6MfARX31RSSwz6l9yN","service":"spop","name":"Dream Tonight","artist":"Chris Medina","album":"What Are Words","type":"song","duration":277,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1IPZCwilyEi0Fqg3WWUtTN","service":"spop","name":"Juliet","artist":"Chris Medina","album":"What Are Words","type":"song","duration":209,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6jhRNXGrN07GPK2Cr1VdDZ","service":"spop","name":"Summer Rain","artist":"Chris Medina","album":"What Are Words","type":"song","duration":258,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5tE5hwlVj2M25ERfO2jpdw","service":"spop","name":"Amazed","artist":"Chris Medina","album":"What Are Words","type":"song","duration":231,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","service":"spop","name":"Possible","artist":"Chris Medina","album":"What Are Words","type":"song","duration":210,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0RAwnhNxm3zvYbSa7WiI8Q","service":"spop","name":"We Can Change The World","artist":"Chris Medina","album":"What Are Words","type":"song","duration":271,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2e8BRFuh2qXXS5btl3Zf7o","service":"spop","name":"Beautiful Eyes","artist":"Chris Medina","album":"What Are Words","type":"song","duration":213,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4p2qQO38X1Ao3viaKeNYgv","service":"spop","name":"Falling In Deeper","artist":"Chris Medina","album":"What Are Words","type":"song","duration":268,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4pv7hzN61NksevP7nRVNHv","service":"spop","name":"Breakeven","artist":"Chris Medina","album":"What Are Words","type":"song","duration":281,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 01 20:53:42 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:42 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:42 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=trace msg="emitting websocket event: will_play" May 01 20:53:42 volumio volumio[840]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","play_origin":"go-librespot"}} May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=debug msg="selected format OGG_VORBIS_320 (834397726e32ad3592b6fffbc5b51bfa6420ee6a)" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:42 volumio go-librespot[1106]: time="2025-05-01T20:53:42+08:00" level=debug msg="requested aes key for file 834397726e32ad3592b6fffbc5b51bfa6420ee6a, gid: 6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:43 volumio volumio[840]: error: Failed request for metavolumio API May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=debug msg="fetched first chunk of 16, total size is 8378052 bytes" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08: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" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=info msg="loaded track \"Don’t Say Goodbye\" (paused: false, position: 0ms, duration: 226306ms, prefetched: false)" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=trace msg="scheduling prefetch in 196s" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=trace msg="emitting websocket event: metadata" May 01 20:53:43 volumio volumio[840]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","name":"Don’t Say Goodbye","artist_names":["Chris Medina"],"album_name":"What Are Words","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","position":0,"duration":226306,"release_date":"year:2011 month:11 day:28","track_number":1,"disc_number":1}} May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:6iOGLZt4sf2esgvLIdc4iY" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:43 volumio go-librespot[1106]: time="2025-05-01T20:53:43+08:00" level=trace msg="emitting websocket event: playing" May 01 20:53:43 volumio volumio[840]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","play_origin":"go-librespot"}} May 01 20:53:43 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:43 volumio volumio[840]: SPOTIFY: {"status":"play","service":"spop","title":"Don’t Say Goodbye","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","trackType":"spotify","seek":0,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:43 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:43 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:43 volumio volumio[840]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Don’t Say Goodbye","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","trackType":"spotify","seek":0,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:43 volumio volumio[840]: verbose: CURRENT POSITION 0 May 01 20:53:43 volumio volumio[840]: info: CoreStateMachine::syncState stateService play May 01 20:53:43 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus stop May 01 20:53:44 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:44 volumio volumio[840]: SPOTIFY: {"status":"play","service":"spop","title":"Don’t Say Goodbye","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","trackType":"spotify","seek":0,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:44 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:44 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:44 volumio volumio[840]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Don’t Say Goodbye","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","trackType":"spotify","seek":0,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:44 volumio volumio[840]: verbose: CURRENT POSITION 0 May 01 20:53:44 volumio volumio[840]: info: CoreStateMachine::syncState stateService play May 01 20:53:44 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus play May 01 20:53:44 volumio volumio[840]: info: Received an update from plugin. extracting info from payload May 01 20:53:44 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:44 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:44 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:44 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:44 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:44 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:44 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:44 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:44 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:44 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:45 volumio volumio[840]: error: Failed request for metavolumio API May 01 20:53:49 volumio volumio[840]: info: Preload queue cleared May 01 20:53:49 volumio volumio[840]: info: CoreCommandRouter::volumioReplaceandPlayItems May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::ClearQueue May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::stop May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::stPlaybackTimer May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:49 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:49 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:49 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:49 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::serviceStop May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::getTrack 0 May 01 20:53:49 volumio volumio[840]: info: CoreCommandRouter::serviceStop May 01 20:53:49 volumio volumio[840]: info: Spotify Stop May 01 20:53:49 volumio volumio[840]: SPOTIFY: SPOTIFY STOP May 01 20:53:49 volumio volumio[840]: SPOTIFY: {"status":"play","position":0,"title":"Don’t Say Goodbye","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","uri":"spotify:track:6iOGLZt4sf2esgvLIdc4iY","trackType":"spotify","codec":"ogg","seek":0,"duration":226,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 01 20:53:49 volumio volumio[840]: info: Sending Spotify command to local API: /player/pause May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::clearPlayQueue May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:49 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::addQueueItems May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::addQueueItems May 01 20:53:49 volumio volumio[840]: info: Preload queue cleared May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:6iOGLZt4sf2esgvLIdc4iY May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:6iOGLZt4sf2esgvLIdc4iY May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:5NxsPRiNuNwrKHpFtgAyBC May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:5NxsPRiNuNwrKHpFtgAyBC May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:6uYiyQpKgwkWuoPEQinz67 May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:6uYiyQpKgwkWuoPEQinz67 May 01 20:53:49 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:49 volumio volumio[840]: info: CoreCommandRouter::volumioPlay May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::play index 2 May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::addQueueItems May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::addQueueItems May 01 20:53:49 volumio volumio[840]: info: Preload queue cleared May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:50A1WCxKycJUHRr4Rz6WrD May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:50A1WCxKycJUHRr4Rz6WrD May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:5wuY6MfARX31RSSwz6l9yN May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:5wuY6MfARX31RSSwz6l9yN May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:0RAwnhNxm3zvYbSa7WiI8Q May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:0RAwnhNxm3zvYbSa7WiI8Q May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:5tE5hwlVj2M25ERfO2jpdw May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:5tE5hwlVj2M25ERfO2jpdw May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:6jhRNXGrN07GPK2Cr1VdDZ May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:6jhRNXGrN07GPK2Cr1VdDZ May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:4p2qQO38X1Ao3viaKeNYgv May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:4p2qQO38X1Ao3viaKeNYgv May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:2e8BRFuh2qXXS5btl3Zf7o May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:2e8BRFuh2qXXS5btl3Zf7o May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:1IPZCwilyEi0Fqg3WWUtTN May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:1IPZCwilyEi0Fqg3WWUtTN May 01 20:53:49 volumio volumio[840]: info: Adding Item to queue: spotify:track:4pv7hzN61NksevP7nRVNHv May 01 20:53:49 volumio volumio[840]: info: Using cached record of: spotify:track:4pv7hzN61NksevP7nRVNHv May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::stop May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:49 volumio volumio[840]: info: CoreCommandRouter::volumioPushQueue May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::saveQueue May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::play index undefined May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::updateTrackBlock May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::getTrackBlock May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:49 volumio volumio[840]: info: CoreStateMachine::startPlaybackTimer May 01 20:53:49 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:49 volumio volumio[840]: info: [1746104029299] ControllerSpotify::clearAddPlayTrack May 01 20:53:49 volumio volumio[840]: info: Sending Spotify command with payload to local API: /player/play May 01 20:53:49 volumio go-librespot[1106]: time="2025-05-01T20:53:49+08:00" level=debug msg="resolved context of track" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:49 volumio go-librespot[1106]: time="2025-05-01T20:53:49+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:49 volumio go-librespot[1106]: time="2025-05-01T20:53:49+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:49 volumio go-librespot[1106]: time="2025-05-01T20:53:49+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:49 volumio go-librespot[1106]: time="2025-05-01T20:53:49+08:00" level=trace msg="emitting websocket event: will_play" May 01 20:53:49 volumio volumio[840]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","play_origin":"go-librespot"}} May 01 20:53:49 volumio go-librespot[1106]: time="2025-05-01T20:53:49+08:00" level=debug msg="selected format OGG_VORBIS_320 (b8c26fc0fec5b0a0de37026b0a82bc5285a2bd2f)" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:49 volumio go-librespot[1106]: time="2025-05-01T20:53:49+08:00" level=debug msg="requested aes key for file b8c26fc0fec5b0a0de37026b0a82bc5285a2bd2f, gid: 6uYiyQpKgwkWuoPEQinz67" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="fetched first chunk of 16, total size is 8339736 bytes" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=info msg="loaded track \"Possible\" (paused: false, position: 0ms, duration: 210093ms, prefetched: false)" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=trace msg="scheduling prefetch in 180s" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=trace msg="emitting websocket event: metadata" May 01 20:53:50 volumio volumio[840]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","name":"Possible","artist_names":["Chris Medina"],"album_name":"What Are Words","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","position":0,"duration":210093,"release_date":"year:2011 month:11 day:28","track_number":3,"disc_number":1}} May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=trace msg="emitting websocket event: playing" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="pause track at 165ms" May 01 20:53:50 volumio volumio[840]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","play_origin":"go-librespot"}} May 01 20:53:50 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:50 volumio volumio[840]: SPOTIFY: {"status":"play","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:50 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:50 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:50 volumio volumio[840]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:50 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:53:50 volumio volumio[840]: info: CoreStateMachine::syncState stateService play May 01 20:53:50 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus stop May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:53:50 volumio go-librespot[1106]: time="2025-05-01T20:53:50+08:00" level=trace msg="emitting websocket event: paused" May 01 20:53:50 volumio volumio[840]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","play_origin":"go-librespot"}} May 01 20:53:50 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:50 volumio volumio[840]: SPOTIFY: {"status":"pause","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:50 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:50 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:50 volumio volumio[840]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:50 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:53:50 volumio volumio[840]: info: CoreStateMachine::syncState stateService pause May 01 20:53:50 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus play May 01 20:53:50 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:50 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:50 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:50 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:50 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:50 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:50 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:53:50 volumio volumio[840]: SPOTIFY: {"status":"pause","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:50 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:53:50 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:50 volumio volumio[840]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:53:50 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:53:50 volumio volumio[840]: info: CoreStateMachine::syncState stateService pause May 01 20:53:50 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus play May 01 20:53:50 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:53:50 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:53:50 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:53:50 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:53:50 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:53:50 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:53:51 volumio go-librespot[1106]: time="2025-05-01T20:53:51+08:00" level=trace msg="sent dealer ping" May 01 20:53:51 volumio go-librespot[1106]: time="2025-05-01T20:53:51+08:00" level=trace msg="received dealer pong" May 01 20:54:02 volumio volumio[840]: info: CoreCommandRouter::volumioPause May 01 20:54:02 volumio volumio[840]: info: CoreStateMachine::pause May 01 20:54:02 volumio volumio[840]: info: CoreStateMachine::stPlaybackTimer May 01 20:54:02 volumio volumio[840]: info: CoreStateMachine::servicePause May 01 20:54:02 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:02 volumio volumio[840]: info: CoreCommandRouter::servicePause May 01 20:54:02 volumio volumio[840]: info: Spotify Received pause May 01 20:54:02 volumio volumio[840]: SPOTIFY: SPOTIFY PAUSE May 01 20:54:02 volumio volumio[840]: SPOTIFY: {"status":"play","position":2,"title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d0000b273c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","codec":"ogg","seek":251,"duration":210,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 01 20:54:02 volumio volumio[840]: info: Sending Spotify command to local API: /player/pause May 01 20:54:02 volumio go-librespot[1106]: time="2025-05-01T20:54:02+08:00" level=debug msg="pause track at 848ms" May 01 20:54:02 volumio go-librespot[1106]: time="2025-05-01T20:54:02+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:54:03 volumio go-librespot[1106]: time="2025-05-01T20:54:03+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:54:03 volumio go-librespot[1106]: time="2025-05-01T20:54:03+08:00" level=trace msg="emitting websocket event: paused" May 01 20:54:03 volumio volumio[840]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","play_origin":"go-librespot"}} May 01 20:54:03 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:54:03 volumio volumio[840]: SPOTIFY: {"status":"pause","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:54:03 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:54:03 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:03 volumio volumio[840]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:54:03 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:54:03 volumio volumio[840]: info: CoreStateMachine::syncState stateService pause May 01 20:54:03 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus pause May 01 20:54:03 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:54:03 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:03 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:54:03 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:54:03 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:54:03 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:54:03 volumio volumio[840]: info: CoreStateMachine::stPlaybackTimer May 01 20:54:04 volumio volumio[840]: info: CoreCommandRouter::volumioPlay May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::play index undefined May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined May 01 20:54:04 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::startPlaybackTimer May 01 20:54:04 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:04 volumio volumio[840]: info: Spotify Resume May 01 20:54:04 volumio volumio[840]: info: Sending Spotify command to local API: /player/resume May 01 20:54:04 volumio go-librespot[1106]: time="2025-05-01T20:54:04+08:00" level=trace msg="seek to 848ms (diff: 232ms, samples: 37396, bytes: 21396)" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:54:04 volumio go-librespot[1106]: time="2025-05-01T20:54:04+08: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" May 01 20:54:04 volumio go-librespot[1106]: time="2025-05-01T20:54:04+08:00" level=debug msg="resume track at 616ms" May 01 20:54:04 volumio kernel: bcm2835-i2s fe203000.i2s: I2S SYNC error! May 01 20:54:04 volumio go-librespot[1106]: time="2025-05-01T20:54:04+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:54:04 volumio go-librespot[1106]: time="2025-05-01T20:54:04+08:00" level=trace msg="scheduling prefetch in 179s" May 01 20:54:04 volumio go-librespot[1106]: time="2025-05-01T20:54:04+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 01 20:54:04 volumio go-librespot[1106]: time="2025-05-01T20:54:04+08:00" level=trace msg="emitting websocket event: playing" May 01 20:54:04 volumio volumio[840]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","play_origin":"go-librespot"}} May 01 20:54:04 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:54:04 volumio volumio[840]: SPOTIFY: {"status":"play","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:54:04 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:54:04 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:04 volumio volumio[840]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:54:04 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::syncState stateService play May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus pause May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:54:04 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:04 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:54:04 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:54:04 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:54:04 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:54:04 volumio volumio[840]: SPOTIFY: PUSH STATE SPOTIFY May 01 20:54:04 volumio volumio[840]: SPOTIFY: {"status":"play","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:54:04 volumio volumio[840]: info: CoreCommandRouter::servicePushState May 01 20:54:04 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:04 volumio volumio[840]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Possible","artist":"Chris Medina","album":"What Are Words","albumart":"https://i.scdn.co/image/ab67616d00001e02c3676f59433092b4949a1e92","uri":"spotify:track:6uYiyQpKgwkWuoPEQinz67","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 01 20:54:04 volumio volumio[840]: verbose: CURRENT POSITION 2 May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::syncState stateService play May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus play May 01 20:54:04 volumio volumio[840]: info: Received an update from plugin. extracting info from payload May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:54:04 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:04 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 01 20:54:04 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:54:04 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:54:04 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:54:04 volumio volumio[840]: info: CoreStateMachine::pushState May 01 20:54:04 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:04 volumio volumio[840]: info: CoreCommandRouter::volumioPushState May 01 20:54:04 volumio volumio[840]: info: MRS: Pushing multiroomSync output update for this device May 01 20:54:04 volumio volumio[840]: info: MRS: Pushing multiroomSync output May 01 20:54:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 01 20:54:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 01 20:54:12 volumio volumio[840]: info: Discovery: Getting this device information May 01 20:54:12 volumio volumio[840]: info: CoreCommandRouter::volumioGetState May 01 20:54:12 volumio volumio[840]: info: CorePlayQueue::getTrack 2 May 01 20:54:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 01 20:54:16 volumio go-librespot[1106]: time="2025-05-01T20:54:16+08:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:6uYiyQpKgwkWuoPEQinz67" May 01 20:54:19 volumio volumio[840]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 01 20:54:19 volumio volumio[840]: Error: connect ETIMEDOUT 118.193.240.37:80 May 01 20:54:19 volumio volumio[840]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { May 01 20:54:19 volumio volumio[840]: errno: -110, May 01 20:54:19 volumio volumio[840]: code: 'ETIMEDOUT', May 01 20:54:19 volumio volumio[840]: syscall: 'connect', May 01 20:54:19 volumio volumio[840]: address: '118.193.240.37', May 01 20:54:19 volumio volumio[840]: port: 80 May 01 20:54:19 volumio volumio[840]: } May 01 20:54:19 volumio volumio[840]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 01 20:54:19 volumio sudo[21598]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-01 20:53 May 01 20:54:19 volumio sudo[21598]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 24 Apr 2025 09:33:57 AM CEST" VOLUMIO_VERSION="3.804" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="354f95cf0a6c2cbcd57b1aca3179c81c"