-- Logs begin at Sun 2024-07-21 11:33:18 CEST, end at Sun 2024-07-21 12:40:34 CEST. -- Jul 21 12:39:08 rivo go-librespot[3808]: time="2024-07-21T12:39:08+02:00" level=debug msg="fetched chunk 10/12, size: 524288" Jul 21 12:39:18 rivo volumio[3129]: verbose: New Socket.io Connection to 192.168.8.173 from 192.168.8.153 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 10 Jul 21 12:39:21 rivo go-librespot[3808]: time="2024-07-21T12:39:21+02:00" level=debug msg="fetched chunk 11/12, size: 524288" Jul 21 12:39:25 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:25 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:25 rivo volumio[3129]: info: CorePlayQueue::getTrack 1 Jul 21 12:39:25 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:25 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:39:25 rivo volumio[3129]: info: CorePlayQueue::getTrack 1 Jul 21 12:39:25 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:39:25 rivo volumio[3129]: info: Spotify Stop Jul 21 12:39:25 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:39:25 rivo volumio[3129]: SPOTIFY: {"status":"play","position":1,"title":"Overdrive (feat. Norma Jean Martine)","artist":"Ofenbach","album":"Overdrive (feat. Norma Jean Martine)","albumart":"https://i.scdn.co/image/ab67616d0000b273249f764814d57dc5dfc462c7","uri":"spotify:track:3bK1zVFBKIzYjmptmI4NsJ","trackType":"spotify","codec":"ogg","seek":311477,"duration":155,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:39:25 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:25 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:25 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:25 rivo volumio[3129]: info: [1721558365656] ControllerSpotify::clearAddPlayTrack Jul 21 12:39:25 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:39:25 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:25 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:25 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:25 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:25 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:25 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:25 rivo go-librespot[3808]: time="2024-07-21T12:39:25+02:00" level=debug msg="pause track at 97882ms" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:39:26 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3bK1zVFBKIzYjmptmI4NsJ","play_origin":"go-librespot"}} Jul 21 12:39:26 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:26 rivo volumio[3129]: 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} Jul 21 12:39:26 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:26 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:26 rivo volumio[3129]: 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} Jul 21 12:39:26 rivo volumio[3129]: verbose: CURRENT POSITION 2 Jul 21 12:39:26 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:26 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:26 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:26 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:26 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:26 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:26 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:26 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:26 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:26 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=debug msg="loading track spotify:track:59NraMJsLaMCVtwXTSia8i (paused: false, position: 0ms)" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:39:26 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","play_origin":"go-librespot"}} Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:59NraMJsLaMCVtwXTSia8i" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=debug msg="requested aes key for file a2478feb52190be548c781d9982742c7df93d624, gid: 59NraMJsLaMCVtwXTSia8i" Jul 21 12:39:26 rivo volumio[3129]: info: camilladsp spawned new process with pid 8040, instance 1, run: true Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=debug msg="fetched first chunk of 13, total size is 6517732 bytes" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Jul 21 12:39:26 rivo go-librespot[3808]: time="2024-07-21T12:39:26+02:00" level=info msg="loaded track \"Prada\" (uri: spotify:track:59NraMJsLaMCVtwXTSia8i, paused: false, position: 0ms, duration: 132359ms)" Jul 21 12:39:26 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:26 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:26 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:26 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 21 12:39:26 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 21 12:39:26 rivo volumio[3129]: info: Discovery: Getting this device information Jul 21 12:39:26 rivo volumio[3129]: info: CoreCommandRouter::volumioGetState Jul 21 12:39:26 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:26 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 21 12:39:26 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:27 rivo go-librespot[3808]: time="2024-07-21T12:39:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:27 rivo go-librespot[3808]: time="2024-07-21T12:39:27+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:39:27 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","name":"Prada","artist_names":["cassö","RAYE","D-Block Europe"],"album_name":"Prada","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e4b7dccdfd54375ded9ccc5c","position":0,"duration":132359,"release_date":"year:2023 month:8 day:11","track_number":1,"disc_number":1}} Jul 21 12:39:27 rivo go-librespot[3808]: time="2024-07-21T12:39:27+02:00" level=debug msg="fetched chunk 1/12, size: 524288" Jul 21 12:39:27 rivo go-librespot[3808]: time="2024-07-21T12:39:27+02:00" level=debug msg="fetched chunk 3/12, size: 524288" Jul 21 12:39:27 rivo go-librespot[3808]: time="2024-07-21T12:39:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:27 rivo go-librespot[3808]: time="2024-07-21T12:39:27+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:39:27 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","play_origin":"go-librespot"}} Jul 21 12:39:27 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:27 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Prada","artist":"cassö, RAYE, D-Block Europe","album":"Prada","albumart":"https://i.scdn.co/image/ab67616d00001e02e4b7dccdfd54375ded9ccc5c","uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","trackType":"spotify","seek":0,"duration":132,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:27 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:27 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:27 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Prada","artist":"cassö, RAYE, D-Block Europe","album":"Prada","albumart":"https://i.scdn.co/image/ab67616d00001e02e4b7dccdfd54375ded9ccc5c","uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","trackType":"spotify","seek":0,"duration":132,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:27 rivo volumio[3129]: verbose: CURRENT POSITION 2 Jul 21 12:39:27 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:27 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:27 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:27 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Prada","artist":"cassö, RAYE, D-Block Europe","album":"Prada","albumart":"https://i.scdn.co/image/ab67616d00001e02e4b7dccdfd54375ded9ccc5c","uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","trackType":"spotify","seek":0,"duration":132,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:27 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:27 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:27 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Prada","artist":"cassö, RAYE, D-Block Europe","album":"Prada","albumart":"https://i.scdn.co/image/ab67616d00001e02e4b7dccdfd54375ded9ccc5c","uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","trackType":"spotify","seek":0,"duration":132,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:27 rivo volumio[3129]: verbose: CURRENT POSITION 2 Jul 21 12:39:27 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:27 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:27 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:27 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:27 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:27 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:27 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:27 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:27 rivo go-librespot[3808]: time="2024-07-21T12:39:27+02:00" level=debug msg="fetched chunk 2/12, size: 524288" Jul 21 12:39:27 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:27 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:27 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:27 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:27 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:27 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:27 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:27 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:27 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:27 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:28 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:28 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:28 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:28 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:28 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:39:28 rivo volumio[3129]: info: CorePlayQueue::getTrack 2 Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:39:28 rivo volumio[3129]: info: Spotify Stop Jul 21 12:39:28 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:39:28 rivo volumio[3129]: SPOTIFY: {"status":"play","position":2,"title":"Prada","artist":"cassö","album":"Prada","albumart":"https://i.scdn.co/image/ab67616d0000b273e4b7dccdfd54375ded9ccc5c","uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","trackType":"spotify","codec":"ogg","seek":0,"duration":132,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:39:28 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:28 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:28 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:28 rivo volumio[3129]: info: [1721558368342] ControllerSpotify::clearAddPlayTrack Jul 21 12:39:28 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:28 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:28 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:28 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:28 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:28 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:28 rivo go-librespot[3808]: time="2024-07-21T12:39:28+02:00" level=debug msg="pause track at 2858ms" Jul 21 12:39:28 rivo go-librespot[3808]: time="2024-07-21T12:39:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:28 rivo go-librespot[3808]: time="2024-07-21T12:39:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:28 rivo go-librespot[3808]: time="2024-07-21T12:39:28+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:39:28 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:59NraMJsLaMCVtwXTSia8i","play_origin":"go-librespot"}} Jul 21 12:39:28 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:28 rivo volumio[3129]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:28 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:28 rivo volumio[3129]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:28 rivo volumio[3129]: verbose: CURRENT POSITION 3 Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:28 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:28 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:28 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:29 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:29 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:29 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:29 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=debug msg="loading track spotify:track:53cHSvMM7cyEcbeUXExOXN (paused: false, position: 0ms)" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:39:29 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","play_origin":"go-librespot"}} Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:53cHSvMM7cyEcbeUXExOXN" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=debug msg="requested aes key for file 228990dee761afeb01345042edd1643c59e510b3, gid: 53cHSvMM7cyEcbeUXExOXN" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=debug msg="fetched first chunk of 14, total size is 7100208 bytes" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=info msg="loaded track \"Strangers\" (uri: spotify:track:53cHSvMM7cyEcbeUXExOXN, paused: false, position: 0ms, duration: 188200ms)" Jul 21 12:39:29 rivo volumio[3129]: info: camilladsp spawned new process with pid 8054, instance 1, run: true Jul 21 12:39:29 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:29 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:29 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:29 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=debug msg="fetched chunk 1/13, size: 524288" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:29 rivo go-librespot[3808]: time="2024-07-21T12:39:29+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:39:29 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","name":"Strangers","artist_names":["NALYRO","Giorgio Gee","Eliine"],"album_name":"Strangers","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ee5ffd12bdffc3a6baf1123a","position":0,"duration":188200,"release_date":"year:2024 month:1 day:5","track_number":1,"disc_number":1}} Jul 21 12:39:30 rivo go-librespot[3808]: time="2024-07-21T12:39:30+02:00" level=debug msg="fetched chunk 2/13, size: 524288" Jul 21 12:39:30 rivo go-librespot[3808]: time="2024-07-21T12:39:30+02:00" level=debug msg="fetched chunk 3/13, size: 524288" Jul 21 12:39:30 rivo go-librespot[3808]: time="2024-07-21T12:39:30+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:30 rivo go-librespot[3808]: time="2024-07-21T12:39:30+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:39:30 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","play_origin":"go-librespot"}} Jul 21 12:39:30 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:30 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Strangers","artist":"NALYRO, Giorgio Gee, Eliine","album":"Strangers","albumart":"https://i.scdn.co/image/ab67616d00001e02ee5ffd12bdffc3a6baf1123a","uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","trackType":"spotify","seek":0,"duration":188,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:30 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:30 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:30 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Strangers","artist":"NALYRO, Giorgio Gee, Eliine","album":"Strangers","albumart":"https://i.scdn.co/image/ab67616d00001e02ee5ffd12bdffc3a6baf1123a","uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","trackType":"spotify","seek":0,"duration":188,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:30 rivo volumio[3129]: verbose: CURRENT POSITION 3 Jul 21 12:39:30 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:30 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:30 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:30 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Strangers","artist":"NALYRO, Giorgio Gee, Eliine","album":"Strangers","albumart":"https://i.scdn.co/image/ab67616d00001e02ee5ffd12bdffc3a6baf1123a","uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","trackType":"spotify","seek":0,"duration":188,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:30 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:30 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:30 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Strangers","artist":"NALYRO, Giorgio Gee, Eliine","album":"Strangers","albumart":"https://i.scdn.co/image/ab67616d00001e02ee5ffd12bdffc3a6baf1123a","uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","trackType":"spotify","seek":0,"duration":188,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:30 rivo volumio[3129]: verbose: CURRENT POSITION 3 Jul 21 12:39:30 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:30 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:30 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:30 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:30 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:30 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:30 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:30 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:30 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:30 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:30 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:30 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:30 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:30 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:30 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:30 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:30 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:30 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:31 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:31 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:31 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:31 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:31 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:31 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:31 rivo volumio[3129]: info: CoreCommandRouter::volumioSeek Jul 21 12:39:31 rivo volumio[3129]: info: CoreStateMachine::seek Jul 21 12:39:31 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:31 rivo volumio[3129]: info: TRACKBLOCK {"uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","service":"spop","name":"Strangers","artist":"NALYRO","album":"Strangers","type":"song","duration":188,"albumart":"https://i.scdn.co/image/ab67616d0000b273ee5ffd12bdffc3a6baf1123a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify","channels":2} Jul 21 12:39:31 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:31 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:31 rivo volumio[3129]: info: Spotify seek to: 58000 Jul 21 12:39:31 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/seek Jul 21 12:39:31 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:31 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:31 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:31 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:31 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:31 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:31 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:31 rivo go-librespot[3808]: time="2024-07-21T12:39:31+02:00" level=debug msg="seek track to 58000ms" Jul 21 12:39:31 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:31 rivo go-librespot[3808]: time="2024-07-21T12:39:31+02:00" level=trace msg="seek to 58000ms (diff: 158ms, samples: 2557800, bytes: 2076141)" Jul 21 12:39:32 rivo go-librespot[3808]: time="2024-07-21T12:39:32+02:00" level=debug msg="fetched chunk 4/13, size: 524288" Jul 21 12:39:32 rivo go-librespot[3808]: time="2024-07-21T12:39:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:32 rivo go-librespot[3808]: time="2024-07-21T12:39:32+02:00" level=trace msg="emitting websocket event: seek" Jul 21 12:39:32 rivo volumio[3129]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","position":58000,"duration":188200,"play_origin":"go-librespot"}} Jul 21 12:39:32 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:32 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Strangers","artist":"NALYRO, Giorgio Gee, Eliine","album":"Strangers","albumart":"https://i.scdn.co/image/ab67616d00001e02ee5ffd12bdffc3a6baf1123a","uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","trackType":"spotify","seek":58000,"duration":188,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:32 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:32 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:32 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Strangers","artist":"NALYRO, Giorgio Gee, Eliine","album":"Strangers","albumart":"https://i.scdn.co/image/ab67616d00001e02ee5ffd12bdffc3a6baf1123a","uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","trackType":"spotify","seek":58000,"duration":188,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:32 rivo volumio[3129]: verbose: CURRENT POSITION 3 Jul 21 12:39:32 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:32 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:32 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:32 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:32 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:32 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:32 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:32 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:32 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:32 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:32 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:32 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:32 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:32 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:32 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:32 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:32 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:32 rivo go-librespot[3808]: time="2024-07-21T12:39:32+02:00" level=debug msg="fetched chunk 5/13, size: 524288" Jul 21 12:39:32 rivo go-librespot[3808]: time="2024-07-21T12:39:32+02:00" level=debug msg="fetched chunk 6/13, size: 524288" Jul 21 12:39:32 rivo go-librespot[3808]: time="2024-07-21T12:39:32+02:00" level=debug msg="fetched chunk 7/13, size: 524288" Jul 21 12:39:33 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:33 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:33 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:33 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:33 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:39:33 rivo volumio[3129]: info: CorePlayQueue::getTrack 3 Jul 21 12:39:33 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:39:33 rivo volumio[3129]: info: Spotify Stop Jul 21 12:39:33 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:39:33 rivo volumio[3129]: SPOTIFY: {"status":"play","position":3,"title":"Strangers","artist":"NALYRO","album":"Strangers","albumart":"https://i.scdn.co/image/ab67616d0000b273ee5ffd12bdffc3a6baf1123a","uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","trackType":"spotify","codec":"ogg","seek":58000,"duration":188,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:39:33 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:33 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:33 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:33 rivo volumio[3129]: info: [1721558373547] ControllerSpotify::clearAddPlayTrack Jul 21 12:39:33 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:39:33 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:33 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:33 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:33 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:33 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:33 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:33 rivo go-librespot[3808]: time="2024-07-21T12:39:33+02:00" level=debug msg="pause track at 59715ms" Jul 21 12:39:33 rivo go-librespot[3808]: time="2024-07-21T12:39:33+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:39:34 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:53cHSvMM7cyEcbeUXExOXN","play_origin":"go-librespot"}} Jul 21 12:39:34 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:34 rivo volumio[3129]: 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} Jul 21 12:39:34 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:34 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:34 rivo volumio[3129]: 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} Jul 21 12:39:34 rivo volumio[3129]: verbose: CURRENT POSITION 4 Jul 21 12:39:34 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:34 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:34 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:34 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:34 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:34 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:34 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:34 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:34 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:34 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=debug msg="loading track spotify:track:0GTuyzPTs2G0wqFD1trSOw (paused: false, position: 0ms)" Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:39:34 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","play_origin":"go-librespot"}} Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:0GTuyzPTs2G0wqFD1trSOw" Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=debug msg="requested aes key for file 3d2c3579b7b922c76065e6bb887c1c43f12ef7d7, gid: 0GTuyzPTs2G0wqFD1trSOw" Jul 21 12:39:34 rivo volumio[3129]: info: camilladsp spawned new process with pid 8070, instance 1, run: true Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=debug msg="fetched first chunk of 14, total size is 6911720 bytes" Jul 21 12:39:34 rivo go-librespot[3808]: time="2024-07-21T12:39:34+02:00" level=trace msg="seek to 0ms (diff: -36ms, samples: 0, bytes: 2213)" Jul 21 12:39:35 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:35 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:35 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:35 rivo go-librespot[3808]: time="2024-07-21T12:39:35+02:00" level=info msg="loaded track \"Phone\" (uri: spotify:track:0GTuyzPTs2G0wqFD1trSOw, paused: false, position: 0ms, duration: 155076ms)" Jul 21 12:39:35 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:35 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:35 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:35 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:35 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:35 rivo go-librespot[3808]: time="2024-07-21T12:39:35+02:00" level=debug msg="fetched chunk 1/13, size: 524288" Jul 21 12:39:35 rivo go-librespot[3808]: time="2024-07-21T12:39:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:35 rivo go-librespot[3808]: time="2024-07-21T12:39:35+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:39:35 rivo go-librespot[3808]: time="2024-07-21T12:39:35+02:00" level=debug msg="fetched chunk 3/13, size: 524288" Jul 21 12:39:35 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","name":"Phone","artist_names":["MEDUZA","Sam Tompkins","Em Beihold"],"album_name":"Phone","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026fd87f346673c7570258d751","position":0,"duration":155076,"release_date":"year:2023 month:7 day:7","track_number":1,"disc_number":1}} Jul 21 12:39:35 rivo go-librespot[3808]: time="2024-07-21T12:39:35+02:00" level=debug msg="fetched chunk 2/13, size: 524288" Jul 21 12:39:35 rivo go-librespot[3808]: time="2024-07-21T12:39:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:35 rivo go-librespot[3808]: time="2024-07-21T12:39:35+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:39:35 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","play_origin":"go-librespot"}} Jul 21 12:39:35 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:35 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Phone","artist":"MEDUZA, Sam Tompkins, Em Beihold","album":"Phone","albumart":"https://i.scdn.co/image/ab67616d00001e026fd87f346673c7570258d751","uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:35 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:35 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:35 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Phone","artist":"MEDUZA, Sam Tompkins, Em Beihold","album":"Phone","albumart":"https://i.scdn.co/image/ab67616d00001e026fd87f346673c7570258d751","uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:35 rivo volumio[3129]: verbose: CURRENT POSITION 4 Jul 21 12:39:35 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:35 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:36 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:36 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Phone","artist":"MEDUZA, Sam Tompkins, Em Beihold","album":"Phone","albumart":"https://i.scdn.co/image/ab67616d00001e026fd87f346673c7570258d751","uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:36 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:36 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:36 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Phone","artist":"MEDUZA, Sam Tompkins, Em Beihold","album":"Phone","albumart":"https://i.scdn.co/image/ab67616d00001e026fd87f346673c7570258d751","uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:36 rivo volumio[3129]: verbose: CURRENT POSITION 4 Jul 21 12:39:36 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:36 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:36 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:36 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:36 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:36 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:36 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:36 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:36 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:36 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:36 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:36 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:36 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:36 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:36 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:36 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:36 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:36 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:36 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:36 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:36 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:36 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:36 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:38 rivo volumio[3129]: info: CoreCommandRouter::volumioSeek Jul 21 12:39:38 rivo volumio[3129]: info: CoreStateMachine::seek Jul 21 12:39:38 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:38 rivo volumio[3129]: info: TRACKBLOCK {"uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","service":"spop","name":"Phone","artist":"MEDUZA","album":"Phone","type":"song","duration":155,"albumart":"https://i.scdn.co/image/ab67616d0000b2736fd87f346673c7570258d751","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify","channels":2} Jul 21 12:39:38 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:38 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:38 rivo volumio[3129]: info: Spotify seek to: 65000 Jul 21 12:39:38 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/seek Jul 21 12:39:38 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:38 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:38 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:38 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:38 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:38 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:39 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:39 rivo go-librespot[3808]: time="2024-07-21T12:39:39+02:00" level=debug msg="seek track to 65000ms" Jul 21 12:39:39 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:39 rivo go-librespot[3808]: time="2024-07-21T12:39:39+02:00" level=debug msg="fetched chunk 7/13, size: 524288" Jul 21 12:39:39 rivo go-librespot[3808]: time="2024-07-21T12:39:39+02:00" level=debug msg="fetched chunk 5/13, size: 524288" Jul 21 12:39:39 rivo go-librespot[3808]: time="2024-07-21T12:39:39+02:00" level=trace msg="seek to 65000ms (diff: 133ms, samples: 2866500, bytes: 2914986)" Jul 21 12:39:39 rivo go-librespot[3808]: time="2024-07-21T12:39:39+02:00" level=debug msg="fetched chunk 8/13, size: 524288" Jul 21 12:39:39 rivo go-librespot[3808]: time="2024-07-21T12:39:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:39 rivo go-librespot[3808]: time="2024-07-21T12:39:39+02:00" level=trace msg="emitting websocket event: seek" Jul 21 12:39:39 rivo volumio[3129]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","position":65000,"duration":155076,"play_origin":"go-librespot"}} Jul 21 12:39:39 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:39 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Phone","artist":"MEDUZA, Sam Tompkins, Em Beihold","album":"Phone","albumart":"https://i.scdn.co/image/ab67616d00001e026fd87f346673c7570258d751","uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","trackType":"spotify","seek":65000,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:39 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:39 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:39 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Phone","artist":"MEDUZA, Sam Tompkins, Em Beihold","album":"Phone","albumart":"https://i.scdn.co/image/ab67616d00001e026fd87f346673c7570258d751","uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","trackType":"spotify","seek":65000,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:39 rivo volumio[3129]: verbose: CURRENT POSITION 4 Jul 21 12:39:39 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:39 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:39 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:39 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:39 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:39 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:39 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:39 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:39 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:39 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:39 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:39 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:39 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:39 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:39 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:39 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:39 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:39 rivo go-librespot[3808]: time="2024-07-21T12:39:39+02:00" level=debug msg="fetched chunk 6/13, size: 524288" Jul 21 12:39:40 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:40 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:40 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:40 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:40 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:39:40 rivo volumio[3129]: info: CorePlayQueue::getTrack 4 Jul 21 12:39:40 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:39:40 rivo volumio[3129]: info: Spotify Stop Jul 21 12:39:40 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:39:40 rivo volumio[3129]: SPOTIFY: {"status":"play","position":4,"title":"Phone","artist":"MEDUZA","album":"Phone","albumart":"https://i.scdn.co/image/ab67616d0000b2736fd87f346673c7570258d751","uri":"spotify:track:0GTuyzPTs2G0wqFD1trSOw","trackType":"spotify","codec":"ogg","seek":65000,"duration":155,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:39:40 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:40 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:40 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:40 rivo volumio[3129]: info: [1721558380208] ControllerSpotify::clearAddPlayTrack Jul 21 12:39:40 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:39:40 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:40 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:40 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:40 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:40 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:40 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:40 rivo go-librespot[3808]: time="2024-07-21T12:39:40+02:00" level=debug msg="pause track at 66158ms" Jul 21 12:39:40 rivo go-librespot[3808]: time="2024-07-21T12:39:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:40 rivo go-librespot[3808]: time="2024-07-21T12:39:40+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:39:40 rivo go-librespot[3808]: time="2024-07-21T12:39:40+02:00" level=debug msg="loading track spotify:track:0h3Xy4V4apMraB5NuM8U7Z (paused: false, position: 1ms)" Jul 21 12:39:40 rivo go-librespot[3808]: time="2024-07-21T12:39:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:40 rivo go-librespot[3808]: time="2024-07-21T12:39:40+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:39:40 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","play_origin":"go-librespot"}} Jul 21 12:39:41 rivo go-librespot[3808]: time="2024-07-21T12:39:41+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:0h3Xy4V4apMraB5NuM8U7Z" Jul 21 12:39:41 rivo go-librespot[3808]: time="2024-07-21T12:39:41+02:00" level=debug msg="requested aes key for file 316785cb685f8ff1b542152a87620426f2fed531, gid: 0h3Xy4V4apMraB5NuM8U7Z" Jul 21 12:39:41 rivo go-librespot[3808]: time="2024-07-21T12:39:41+02:00" level=debug msg="fetched first chunk of 16, total size is 8157712 bytes" Jul 21 12:39:41 rivo go-librespot[3808]: time="2024-07-21T12:39:41+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" Jul 21 12:39:41 rivo go-librespot[3808]: time="2024-07-21T12:39:41+02:00" level=info msg="loaded track \"Stumblin' In\" (uri: spotify:track:0h3Xy4V4apMraB5NuM8U7Z, paused: false, position: 1ms, duration: 213363ms)" Jul 21 12:39:41 rivo volumio[3129]: info: camilladsp spawned new process with pid 8129, instance 1, run: true Jul 21 12:39:41 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:41 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:41 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:41 rivo volumio[3129]: error: FusionDsp - WebSocket error: [object Object] Jul 21 12:39:41 rivo go-librespot[3808]: time="2024-07-21T12:39:41+02:00" level=debug msg="fetched chunk 1/15, size: 524288" Jul 21 12:39:41 rivo go-librespot[3808]: time="2024-07-21T12:39:41+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:41 rivo go-librespot[3808]: time="2024-07-21T12:39:41+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:39:41 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","name":"Stumblin' In","artist_names":["CYRIL"],"album_name":"Stumblin' In","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","position":1,"duration":213363,"release_date":"year:2023 month:11 day:10","track_number":1,"disc_number":1}} Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::volumioSeek Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::seek Jul 21 12:39:42 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:42 rivo volumio[3129]: info: TRACKBLOCK {"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","service":"spop","name":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","type":"song","duration":213,"albumart":"https://i.scdn.co/image/ab67616d0000b2739a903819d8a5d3c80c47734c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"} Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:42 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:42 rivo volumio[3129]: info: Spotify seek to: 64000 Jul 21 12:39:42 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/seek Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:42 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:42 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:42 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:42 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:42 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=debug msg="fetched chunk 2/15, size: 524288" Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=debug msg="fetched chunk 3/15, size: 524288" Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=debug msg="seek track to 64000ms" Jul 21 12:39:42 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","play_origin":"go-librespot"}} Jul 21 12:39:42 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:42 rivo volumio[3129]: SPOTIFY: {"status":"pause","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":1,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:42 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:42 rivo volumio[3129]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":1,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:42 rivo volumio[3129]: verbose: CURRENT POSITION 5 Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:42 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:42 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:42 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:42 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:42 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=debug msg="fetched chunk 4/15, size: 524288" Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=trace msg="seek to 64000ms (diff: 77ms, samples: 2822400, bytes: 2396135)" Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=trace msg="emitting websocket event: seek" Jul 21 12:39:42 rivo volumio[3129]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","position":64000,"duration":213363,"play_origin":"go-librespot"}} Jul 21 12:39:42 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:42 rivo volumio[3129]: SPOTIFY: {"status":"pause","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":64000,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:42 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:42 rivo volumio[3129]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":64000,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:42 rivo volumio[3129]: verbose: CURRENT POSITION 5 Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:42 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:42 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:42 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:42 rivo go-librespot[3808]: time="2024-07-21T12:39:42+02:00" level=debug msg="fetched chunk 5/15, size: 524288" Jul 21 12:39:42 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:42 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:43 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:43 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:43 rivo go-librespot[3808]: time="2024-07-21T12:39:43+02:00" level=debug msg="fetched chunk 6/15, size: 524288" Jul 21 12:39:43 rivo go-librespot[3808]: time="2024-07-21T12:39:43+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:43 rivo go-librespot[3808]: time="2024-07-21T12:39:43+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:39:43 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","play_origin":"go-librespot"}} Jul 21 12:39:43 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:43 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":64000,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:43 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:43 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:43 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":64000,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:43 rivo volumio[3129]: verbose: CURRENT POSITION 5 Jul 21 12:39:43 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:43 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:43 rivo go-librespot[3808]: time="2024-07-21T12:39:43+02:00" level=debug msg="fetched chunk 7/15, size: 524288" Jul 21 12:39:43 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:43 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":64000,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:43 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:43 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:43 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e029a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":64000,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:43 rivo volumio[3129]: verbose: CURRENT POSITION 5 Jul 21 12:39:43 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:43 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:43 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:43 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:43 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:43 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:43 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:43 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:43 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:43 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:43 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:43 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:43 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:43 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:43 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:43 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:43 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:43 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:44 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:44 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:44 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:44 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:44 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:44 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:46 rivo go-librespot[3808]: time="2024-07-21T12:39:46+02:00" level=debug msg="fetched chunk 8/15, size: 524288" Jul 21 12:39:47 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:47 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:47 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:47 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:47 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:39:47 rivo volumio[3129]: info: CorePlayQueue::getTrack 5 Jul 21 12:39:47 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:39:47 rivo volumio[3129]: info: Spotify Stop Jul 21 12:39:47 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:39:47 rivo volumio[3129]: SPOTIFY: {"status":"play","position":5,"title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d0000b2739a903819d8a5d3c80c47734c","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","codec":"ogg","seek":64000,"duration":213,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:39:47 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:47 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:47 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:47 rivo volumio[3129]: info: [1721558387264] ControllerSpotify::clearAddPlayTrack Jul 21 12:39:47 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:47 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:47 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:47 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:47 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:47 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=debug msg="pause track at 69162ms" Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:39:47 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","play_origin":"go-librespot"}} Jul 21 12:39:47 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:47 rivo volumio[3129]: 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} Jul 21 12:39:47 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:47 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:47 rivo volumio[3129]: 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} Jul 21 12:39:47 rivo volumio[3129]: verbose: CURRENT POSITION 6 Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:47 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:47 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:47 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:47 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:47 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:47 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:47 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:47 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=debug msg="loading track spotify:track:5OFVzqSeFxGpvDGyHvVeLj (paused: false, position: 0ms)" Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:39:47 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","play_origin":"go-librespot"}} Jul 21 12:39:47 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5OFVzqSeFxGpvDGyHvVeLj" Jul 21 12:39:48 rivo go-librespot[3808]: time="2024-07-21T12:39:47+02:00" level=debug msg="requested aes key for file bc68015731c55a9fac90d50d37f75c424fc63a17, gid: 5OFVzqSeFxGpvDGyHvVeLj" Jul 21 12:39:48 rivo volumio[3129]: info: camilladsp spawned new process with pid 8143, instance 1, run: true Jul 21 12:39:48 rivo go-librespot[3808]: time="2024-07-21T12:39:48+02:00" level=debug msg="fetched first chunk of 13, total size is 6464879 bytes" Jul 21 12:39:48 rivo go-librespot[3808]: time="2024-07-21T12:39:48+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Jul 21 12:39:48 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:48 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:48 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:48 rivo go-librespot[3808]: time="2024-07-21T12:39:48+02:00" level=info msg="loaded track \"It's Not Right But It's Okay\" (uri: spotify:track:5OFVzqSeFxGpvDGyHvVeLj, paused: false, position: 0ms, duration: 152304ms)" Jul 21 12:39:48 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:48 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:48 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:48 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:48 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:48 rivo go-librespot[3808]: time="2024-07-21T12:39:48+02:00" level=debug msg="fetched chunk 2/12, size: 524288" Jul 21 12:39:48 rivo go-librespot[3808]: time="2024-07-21T12:39:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:48 rivo go-librespot[3808]: time="2024-07-21T12:39:48+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:39:48 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","name":"It's Not Right But It's Okay","artist_names":["Mr. Belt \u0026 Wezol"],"album_name":"It's Not Right But It's Okay","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0203f9f7783244b38aec79cb6d","position":0,"duration":152304,"release_date":"year:2024 month:2 day:23","track_number":1,"disc_number":1}} Jul 21 12:39:49 rivo go-librespot[3808]: time="2024-07-21T12:39:49+02:00" level=debug msg="fetched chunk 1/12, size: 524288" Jul 21 12:39:49 rivo go-librespot[3808]: time="2024-07-21T12:39:49+02:00" level=debug msg="fetched chunk 3/12, size: 524288" Jul 21 12:39:49 rivo go-librespot[3808]: time="2024-07-21T12:39:49+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:49 rivo go-librespot[3808]: time="2024-07-21T12:39:49+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:39:49 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","play_origin":"go-librespot"}} Jul 21 12:39:49 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:49 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"It's Not Right But It's Okay","artist":"Mr. Belt & Wezol","album":"It's Not Right But It's Okay","albumart":"https://i.scdn.co/image/ab67616d00001e0203f9f7783244b38aec79cb6d","uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","trackType":"spotify","seek":0,"duration":152,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:49 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:49 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:49 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"It's Not Right But It's Okay","artist":"Mr. Belt & Wezol","album":"It's Not Right But It's Okay","albumart":"https://i.scdn.co/image/ab67616d00001e0203f9f7783244b38aec79cb6d","uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","trackType":"spotify","seek":0,"duration":152,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:49 rivo volumio[3129]: verbose: CURRENT POSITION 6 Jul 21 12:39:49 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:49 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:49 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:49 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"It's Not Right But It's Okay","artist":"Mr. Belt & Wezol","album":"It's Not Right But It's Okay","albumart":"https://i.scdn.co/image/ab67616d00001e0203f9f7783244b38aec79cb6d","uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","trackType":"spotify","seek":0,"duration":152,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:49 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:49 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:49 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"It's Not Right But It's Okay","artist":"Mr. Belt & Wezol","album":"It's Not Right But It's Okay","albumart":"https://i.scdn.co/image/ab67616d00001e0203f9f7783244b38aec79cb6d","uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","trackType":"spotify","seek":0,"duration":152,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:49 rivo volumio[3129]: verbose: CURRENT POSITION 6 Jul 21 12:39:49 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:49 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:49 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:49 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:49 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:49 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:49 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:49 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:49 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:49 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:49 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:49 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:49 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:49 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:49 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:49 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:49 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:49 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:49 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:49 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:49 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:49 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:49 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:49 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:50 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:50 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:50 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:50 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:50 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:39:50 rivo volumio[3129]: info: CorePlayQueue::getTrack 6 Jul 21 12:39:50 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:39:50 rivo volumio[3129]: info: Spotify Stop Jul 21 12:39:50 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:39:50 rivo volumio[3129]: SPOTIFY: {"status":"play","position":6,"title":"It's Not Right But It's Okay","artist":"Mr. Belt & Wezol","album":"It's Not Right But It's Okay","albumart":"https://i.scdn.co/image/ab67616d0000b27303f9f7783244b38aec79cb6d","uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","trackType":"spotify","codec":"ogg","seek":0,"duration":152,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:39:50 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:50 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:50 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:50 rivo volumio[3129]: info: [1721558390267] ControllerSpotify::clearAddPlayTrack Jul 21 12:39:50 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:50 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:50 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:50 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:50 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:50 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=debug msg="pause track at 2872ms" Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:39:50 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5OFVzqSeFxGpvDGyHvVeLj","play_origin":"go-librespot"}} Jul 21 12:39:50 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:50 rivo volumio[3129]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:50 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:50 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:50 rivo volumio[3129]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:50 rivo volumio[3129]: verbose: CURRENT POSITION 7 Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:50 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:50 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:50 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:50 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:50 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:50 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:50 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:50 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=debug msg="loading track spotify:track:70aSLeUZdk85z5zq0TInw5 (paused: false, position: 0ms)" Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:39:50 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","play_origin":"go-librespot"}} Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:70aSLeUZdk85z5zq0TInw5" Jul 21 12:39:50 rivo go-librespot[3808]: time="2024-07-21T12:39:50+02:00" level=debug msg="requested aes key for file 536dbae84ca86e3294707e33e198ddcca6156466, gid: 70aSLeUZdk85z5zq0TInw5" Jul 21 12:39:51 rivo volumio[3129]: info: camilladsp spawned new process with pid 8157, instance 1, run: true Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=debug msg="fetched first chunk of 13, total size is 6669708 bytes" Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=trace msg="seek to 0ms (diff: -15ms, samples: 0, bytes: 2542)" Jul 21 12:39:51 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:51 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:51 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:51 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:51 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:51 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=info msg="loaded track \"Missing\" (uri: spotify:track:70aSLeUZdk85z5zq0TInw5, paused: false, position: 0ms, duration: 175680ms)" Jul 21 12:39:51 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:51 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=debug msg="fetched chunk 1/12, size: 524288" Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:39:51 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","name":"Missing","artist_names":["Giorgio Gee","SRNDE"],"album_name":"Missing","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f16d18a3dc6eec64f3160ad7","position":0,"duration":175680,"release_date":"year:2024 month:5 day:24","track_number":1,"disc_number":1}} Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=debug msg="fetched chunk 3/12, size: 524288" Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:39:51 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","play_origin":"go-librespot"}} Jul 21 12:39:51 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:51 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Missing","artist":"Giorgio Gee, SRNDE","album":"Missing","albumart":"https://i.scdn.co/image/ab67616d00001e02f16d18a3dc6eec64f3160ad7","uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","trackType":"spotify","seek":0,"duration":175,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:51 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:51 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:51 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Missing","artist":"Giorgio Gee, SRNDE","album":"Missing","albumart":"https://i.scdn.co/image/ab67616d00001e02f16d18a3dc6eec64f3160ad7","uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","trackType":"spotify","seek":0,"duration":175,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:51 rivo volumio[3129]: verbose: CURRENT POSITION 7 Jul 21 12:39:51 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:51 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:51 rivo go-librespot[3808]: time="2024-07-21T12:39:51+02:00" level=debug msg="fetched chunk 2/12, size: 524288" Jul 21 12:39:52 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:52 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Missing","artist":"Giorgio Gee, SRNDE","album":"Missing","albumart":"https://i.scdn.co/image/ab67616d00001e02f16d18a3dc6eec64f3160ad7","uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","trackType":"spotify","seek":0,"duration":175,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:52 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:52 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:52 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Missing","artist":"Giorgio Gee, SRNDE","album":"Missing","albumart":"https://i.scdn.co/image/ab67616d00001e02f16d18a3dc6eec64f3160ad7","uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","trackType":"spotify","seek":0,"duration":175,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:52 rivo volumio[3129]: verbose: CURRENT POSITION 7 Jul 21 12:39:52 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:52 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:52 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:52 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:52 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:52 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:52 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:52 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:52 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:52 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:52 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:52 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:52 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:52 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:52 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:52 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:52 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:52 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:52 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:52 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:52 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:52 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:52 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:53 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:53 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:53 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:53 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:53 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:39:53 rivo volumio[3129]: info: CorePlayQueue::getTrack 7 Jul 21 12:39:53 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:39:53 rivo volumio[3129]: info: Spotify Stop Jul 21 12:39:53 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:39:53 rivo volumio[3129]: SPOTIFY: {"status":"play","position":7,"title":"Missing","artist":"Giorgio Gee","album":"Missing","albumart":"https://i.scdn.co/image/ab67616d0000b273f16d18a3dc6eec64f3160ad7","uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","trackType":"spotify","codec":"ogg","seek":0,"duration":175,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:39:53 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:53 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:53 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:53 rivo volumio[3129]: info: [1721558393336] ControllerSpotify::clearAddPlayTrack Jul 21 12:39:53 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:53 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:53 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:53 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:53 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:53 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:53 rivo go-librespot[3808]: time="2024-07-21T12:39:53+02:00" level=debug msg="pause track at 3156ms" Jul 21 12:39:53 rivo go-librespot[3808]: time="2024-07-21T12:39:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:53 rivo volumio[3129]: error: Failed request for metavolumio API Jul 21 12:39:53 rivo go-librespot[3808]: time="2024-07-21T12:39:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:53 rivo go-librespot[3808]: time="2024-07-21T12:39:53+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:39:53 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:70aSLeUZdk85z5zq0TInw5","play_origin":"go-librespot"}} Jul 21 12:39:53 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:53 rivo volumio[3129]: 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} Jul 21 12:39:53 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:53 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:53 rivo volumio[3129]: 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} Jul 21 12:39:53 rivo volumio[3129]: verbose: CURRENT POSITION 8 Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:53 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:53 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:53 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:53 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:53 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:53 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:53 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:53 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:53 rivo go-librespot[3808]: time="2024-07-21T12:39:53+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:39:53 rivo go-librespot[3808]: time="2024-07-21T12:39:53+02:00" level=debug msg="loading track spotify:track:6BePGk3eCan4FqaW2X8Qy3 (paused: false, position: 0ms)" Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:39:54 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","play_origin":"go-librespot"}} Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6BePGk3eCan4FqaW2X8Qy3" Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=debug msg="requested aes key for file e3b0462d22ddd3ef2ef08bcc9a92767197ed565c, gid: 6BePGk3eCan4FqaW2X8Qy3" Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=debug msg="fetched first chunk of 15, total size is 7624372 bytes" Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Jul 21 12:39:54 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=info msg="loaded track \"10:35\" (uri: spotify:track:6BePGk3eCan4FqaW2X8Qy3, paused: false, position: 0ms, duration: 172252ms)" Jul 21 12:39:54 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:54 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:54 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:54 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:54 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:54 rivo volumio[3129]: error: FusionDsp - WebSocket error: [object Object] Jul 21 12:39:54 rivo volumio[3129]: info: camilladsp spawned new process with pid 8172, instance 1, run: true Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=debug msg="fetched chunk 3/14, size: 524288" Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:54 rivo go-librespot[3808]: time="2024-07-21T12:39:54+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:39:54 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","name":"10:35","artist_names":["Tiësto","Tate McRae"],"album_name":"10:35","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02999565cd8bea3f8f0985bb31","position":0,"duration":172252,"release_date":"year:2022 month:11 day:3","track_number":1,"disc_number":1}} Jul 21 12:39:55 rivo go-librespot[3808]: time="2024-07-21T12:39:55+02:00" level=debug msg="fetched chunk 1/14, size: 524288" Jul 21 12:39:55 rivo go-librespot[3808]: time="2024-07-21T12:39:55+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:55 rivo go-librespot[3808]: time="2024-07-21T12:39:55+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:39:55 rivo go-librespot[3808]: time="2024-07-21T12:39:55+02:00" level=debug msg="fetched chunk 2/14, size: 524288" Jul 21 12:39:55 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","play_origin":"go-librespot"}} Jul 21 12:39:55 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:55 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"10:35","artist":"Tiësto, Tate McRae","album":"10:35","albumart":"https://i.scdn.co/image/ab67616d00001e02999565cd8bea3f8f0985bb31","uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","trackType":"spotify","seek":0,"duration":172,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:55 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:55 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:55 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"10:35","artist":"Tiësto, Tate McRae","album":"10:35","albumart":"https://i.scdn.co/image/ab67616d00001e02999565cd8bea3f8f0985bb31","uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","trackType":"spotify","seek":0,"duration":172,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:55 rivo volumio[3129]: verbose: CURRENT POSITION 8 Jul 21 12:39:55 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:55 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:55 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:55 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"10:35","artist":"Tiësto, Tate McRae","album":"10:35","albumart":"https://i.scdn.co/image/ab67616d00001e02999565cd8bea3f8f0985bb31","uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","trackType":"spotify","seek":0,"duration":172,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:55 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:55 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:55 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"10:35","artist":"Tiësto, Tate McRae","album":"10:35","albumart":"https://i.scdn.co/image/ab67616d00001e02999565cd8bea3f8f0985bb31","uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","trackType":"spotify","seek":0,"duration":172,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:55 rivo volumio[3129]: verbose: CURRENT POSITION 8 Jul 21 12:39:55 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:55 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:55 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:39:55 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:55 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:55 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:55 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:55 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:55 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:55 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:55 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:55 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:55 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:55 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:55 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:55 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:55 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:55 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:55 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:55 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:55 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:55 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:55 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:55 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:56 rivo volumio[3129]: info: CoreCommandRouter::volumioSeek Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::seek Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:56 rivo volumio[3129]: info: TRACKBLOCK {"uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","service":"spop","name":"10:35","artist":"Tiësto","album":"10:35","type":"song","duration":172,"albumart":"https://i.scdn.co/image/ab67616d0000b273999565cd8bea3f8f0985bb31","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify","channels":2} Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:56 rivo volumio[3129]: info: Spotify seek to: 60000 Jul 21 12:39:56 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/seek Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:56 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:56 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:56 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:56 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:56 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:56 rivo go-librespot[3808]: time="2024-07-21T12:39:56+02:00" level=debug msg="seek track to 60000ms" Jul 21 12:39:56 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:56 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:56 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:56 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrack 8 Jul 21 12:39:56 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:39:56 rivo volumio[3129]: info: Spotify Stop Jul 21 12:39:56 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:39:56 rivo volumio[3129]: SPOTIFY: {"status":"play","position":8,"title":"10:35","artist":"Tiësto","album":"10:35","albumart":"https://i.scdn.co/image/ab67616d0000b273999565cd8bea3f8f0985bb31","uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","trackType":"spotify","codec":"ogg","seek":60000,"duration":172,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:39:56 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:56 rivo volumio[3129]: info: [1721558396622] ControllerSpotify::clearAddPlayTrack Jul 21 12:39:56 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:39:56 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:39:56 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:39:56 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:56 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:56 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:56 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:56 rivo go-librespot[3808]: time="2024-07-21T12:39:56+02:00" level=debug msg="fetched chunk 4/14, size: 524288" Jul 21 12:39:56 rivo go-librespot[3808]: time="2024-07-21T12:39:56+02:00" level=trace msg="seek to 60000ms (diff: 231ms, samples: 2646000, bytes: 2470320)" Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=trace msg="emitting websocket event: seek" Jul 21 12:39:57 rivo volumio[3129]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:6BePGk3eCan4FqaW2X8Qy3","position":60000,"duration":172252,"play_origin":"go-librespot"}} Jul 21 12:39:57 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:57 rivo volumio[3129]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":60000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:57 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:57 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:57 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:57 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:57 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:57 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:57 rivo volumio[3129]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":60000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:57 rivo volumio[3129]: verbose: CURRENT POSITION 9 Jul 21 12:39:57 rivo volumio[3129]: info: CoreStateMachine::syncState stateService stop Jul 21 12:39:57 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:57 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:57 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:57 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:57 rivo volumio[3129]: info: No code Jul 21 12:39:57 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:57 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:57 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:57 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:57 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:57 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:57 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=debug msg="fetched chunk 7/14, size: 524288" Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=debug msg="fetched chunk 5/14, size: 524288" Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=debug msg="loading track spotify:track:4FtVOZM48CHrItbrqfn9Sd (paused: false, position: 102ms)" Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=debug msg="fetched chunk 6/14, size: 524288" Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:57 rivo go-librespot[3808]: time="2024-07-21T12:39:57+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:39:57 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","play_origin":"go-librespot"}} Jul 21 12:39:58 rivo go-librespot[3808]: time="2024-07-21T12:39:58+02:00" level=debug msg="fetched chunk 8/14, size: 524288" Jul 21 12:39:58 rivo go-librespot[3808]: time="2024-07-21T12:39:58+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:4FtVOZM48CHrItbrqfn9Sd" Jul 21 12:39:58 rivo go-librespot[3808]: time="2024-07-21T12:39:58+02:00" level=debug msg="requested aes key for file c597eedb84ad4c79f41b61a92d6fe6678a155ae6, gid: 4FtVOZM48CHrItbrqfn9Sd" Jul 21 12:39:58 rivo volumio[3129]: info: camilladsp spawned new process with pid 8186, instance 1, run: true Jul 21 12:39:58 rivo go-librespot[3808]: time="2024-07-21T12:39:58+02:00" level=debug msg="fetched first chunk of 14, total size is 7108492 bytes" Jul 21 12:39:58 rivo go-librespot[3808]: time="2024-07-21T12:39:58+02:00" level=trace msg="seek to 102ms (diff: 102ms, samples: 4498, bytes: 0)" Jul 21 12:39:58 rivo go-librespot[3808]: time="2024-07-21T12:39:58+02:00" level=info msg="loaded track \"With You\" (uri: spotify:track:4FtVOZM48CHrItbrqfn9Sd, paused: false, position: 102ms, duration: 168398ms)" Jul 21 12:39:58 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:39:58 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:39:58 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:58 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=debug msg="fetched chunk 1/13, size: 524288" Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:39:59 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","name":"With You","artist_names":["Lynnic","ItsArius","Dinia"],"album_name":"With You","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","position":102,"duration":168398,"release_date":"year:2023 month:9 day:22","track_number":1,"disc_number":1}} Jul 21 12:39:59 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:59 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:59 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:59 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:59 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:39:59 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=debug msg="pause track at 1827ms" Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=debug msg="fetched chunk 3/13, size: 524288" Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=debug msg="fetched chunk 2/13, size: 524288" Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:39:59 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","play_origin":"go-librespot"}} Jul 21 12:39:59 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:59 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"With You","artist":"Lynnic, ItsArius, Dinia","album":"With You","albumart":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","seek":102,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:59 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:59 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:59 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"With You","artist":"Lynnic, ItsArius, Dinia","album":"With You","albumart":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","seek":102,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:59 rivo volumio[3129]: verbose: CURRENT POSITION 9 Jul 21 12:39:59 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:39:59 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:39:59 rivo go-librespot[3808]: time="2024-07-21T12:39:59+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:39:59 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","play_origin":"go-librespot"}} Jul 21 12:39:59 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:39:59 rivo volumio[3129]: SPOTIFY: {"status":"pause","service":"spop","title":"With You","artist":"Lynnic, ItsArius, Dinia","album":"With You","albumart":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","seek":102,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:59 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:39:59 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:59 rivo volumio[3129]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"With You","artist":"Lynnic, ItsArius, Dinia","album":"With You","albumart":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","seek":102,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:39:59 rivo volumio[3129]: verbose: CURRENT POSITION 9 Jul 21 12:39:59 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:39:59 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:39:59 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:39:59 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:39:59 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:39:59 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:39:59 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:39:59 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:39:59 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:39:59 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:00 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:40:00 rivo volumio[3129]: SPOTIFY: {"status":"pause","service":"spop","title":"With You","artist":"Lynnic, ItsArius, Dinia","album":"With You","albumart":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","seek":102,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:00 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:40:00 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:00 rivo volumio[3129]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"With You","artist":"Lynnic, ItsArius, Dinia","album":"With You","albumart":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","seek":102,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:00 rivo volumio[3129]: verbose: CURRENT POSITION 9 Jul 21 12:40:00 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:40:00 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:40:00 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:00 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:00 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:00 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:00 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:00 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:00 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:00 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:00 rivo volumio[3129]: info: camilladsp spawned new process with pid 8197, instance 1, run: true Jul 21 12:40:05 rivo volumio[3129]: info: CoreCommandRouter::volumioSeek Jul 21 12:40:05 rivo volumio[3129]: info: CoreStateMachine::seek Jul 21 12:40:05 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:05 rivo volumio[3129]: info: TRACKBLOCK {"uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","service":"spop","name":"With You","artist":"Lynnic","album":"With You","type":"song","duration":168,"albumart":"https://i.scdn.co/image/ab67616d0000b2736c303579cdd6c93204f090ef","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"} Jul 21 12:40:05 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:40:05 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:05 rivo volumio[3129]: info: Spotify seek to: 50000 Jul 21 12:40:05 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/seek Jul 21 12:40:05 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:05 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:05 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:05 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:05 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:05 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:05 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:05 rivo go-librespot[3808]: time="2024-07-21T12:40:05+02:00" level=debug msg="seek track to 50000ms" Jul 21 12:40:05 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:06 rivo go-librespot[3808]: time="2024-07-21T12:40:06+02:00" level=debug msg="fetched chunk 4/13, size: 524288" Jul 21 12:40:06 rivo go-librespot[3808]: time="2024-07-21T12:40:06+02:00" level=trace msg="seek to 50000ms (diff: 66ms, samples: 2205000, bytes: 2099067)" Jul 21 12:40:06 rivo go-librespot[3808]: time="2024-07-21T12:40:06+02:00" level=debug msg="fetched chunk 5/13, size: 524288" Jul 21 12:40:06 rivo go-librespot[3808]: time="2024-07-21T12:40:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:06 rivo go-librespot[3808]: time="2024-07-21T12:40:06+02:00" level=trace msg="emitting websocket event: seek" Jul 21 12:40:06 rivo volumio[3129]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","position":50000,"duration":168398,"play_origin":"go-librespot"}} Jul 21 12:40:06 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:40:06 rivo volumio[3129]: SPOTIFY: {"status":"pause","service":"spop","title":"With You","artist":"Lynnic, ItsArius, Dinia","album":"With You","albumart":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","seek":50000,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:06 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:40:06 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:06 rivo volumio[3129]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"With You","artist":"Lynnic, ItsArius, Dinia","album":"With You","albumart":"https://i.scdn.co/image/ab67616d00001e026c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","seek":50000,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:06 rivo volumio[3129]: verbose: CURRENT POSITION 9 Jul 21 12:40:06 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:40:06 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:40:06 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:06 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:06 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:06 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:06 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:06 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:06 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:06 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:06 rivo go-librespot[3808]: time="2024-07-21T12:40:06+02:00" level=debug msg="fetched chunk 6/13, size: 524288" Jul 21 12:40:06 rivo go-librespot[3808]: time="2024-07-21T12:40:06+02:00" level=debug msg="fetched chunk 7/13, size: 524288" Jul 21 12:40:16 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:40:16 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:16 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:16 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:16 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:40:16 rivo volumio[3129]: info: CorePlayQueue::getTrack 9 Jul 21 12:40:16 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:40:16 rivo volumio[3129]: info: Spotify Stop Jul 21 12:40:16 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:40:16 rivo volumio[3129]: SPOTIFY: {"status":"play","position":9,"title":"With You","artist":"Lynnic","album":"With You","albumart":"https://i.scdn.co/image/ab67616d0000b2736c303579cdd6c93204f090ef","uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","trackType":"spotify","codec":"ogg","seek":51114,"duration":168,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:40:16 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:40:16 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:40:16 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:16 rivo volumio[3129]: info: [1721558416034] ControllerSpotify::clearAddPlayTrack Jul 21 12:40:16 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:40:16 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:40:16 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:16 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:16 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=debug msg="pause track at 49934ms" Jul 21 12:40:16 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:40:16 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4FtVOZM48CHrItbrqfn9Sd","play_origin":"go-librespot"}} Jul 21 12:40:16 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:40:16 rivo volumio[3129]: 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} Jul 21 12:40:16 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:40:16 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:16 rivo volumio[3129]: 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} Jul 21 12:40:16 rivo volumio[3129]: verbose: CURRENT POSITION 10 Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:40:16 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:16 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:16 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:16 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:16 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:16 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:16 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:16 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=debug msg="loading track spotify:track:1YexFEloUaShjmXGE0iPR1 (paused: false, position: 0ms)" Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:40:16 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","play_origin":"go-librespot"}} Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:1YexFEloUaShjmXGE0iPR1" Jul 21 12:40:16 rivo go-librespot[3808]: time="2024-07-21T12:40:16+02:00" level=debug msg="requested aes key for file cd4db83ae9cd6bf9bd92968f27e9e972b3525266, gid: 1YexFEloUaShjmXGE0iPR1" Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=debug msg="fetched first chunk of 19, total size is 9533808 bytes" Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=info msg="loaded track \"Mwaki\" (uri: spotify:track:1YexFEloUaShjmXGE0iPR1, paused: false, position: 0ms, duration: 208135ms)" Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=debug msg="fetched chunk 1/18, size: 524288" Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:40:17 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","name":"Mwaki","artist_names":["Zerb","Sofiya Nzau"],"album_name":"Mwaki (Major Lazer Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021a6508c19c3bc140f707f319","position":0,"duration":208135,"release_date":"year:2024 month:1 day:12","track_number":3,"disc_number":1}} Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=debug msg="fetched chunk 3/18, size: 524288" Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=debug msg="fetched chunk 2/18, size: 524288" Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:17 rivo go-librespot[3808]: time="2024-07-21T12:40:17+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:40:17 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","play_origin":"go-librespot"}} Jul 21 12:40:17 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:40:17 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Mwaki","artist":"Zerb, Sofiya Nzau","album":"Mwaki (Major Lazer Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e021a6508c19c3bc140f707f319","uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","trackType":"spotify","seek":0,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:17 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:40:17 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:17 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Mwaki","artist":"Zerb, Sofiya Nzau","album":"Mwaki (Major Lazer Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e021a6508c19c3bc140f707f319","uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","trackType":"spotify","seek":0,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:17 rivo volumio[3129]: verbose: CURRENT POSITION 10 Jul 21 12:40:17 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:40:17 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:40:17 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:40:17 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Mwaki","artist":"Zerb, Sofiya Nzau","album":"Mwaki (Major Lazer Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e021a6508c19c3bc140f707f319","uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","trackType":"spotify","seek":0,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:17 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:40:17 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:17 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Mwaki","artist":"Zerb, Sofiya Nzau","album":"Mwaki (Major Lazer Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e021a6508c19c3bc140f707f319","uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","trackType":"spotify","seek":0,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:17 rivo volumio[3129]: verbose: CURRENT POSITION 10 Jul 21 12:40:17 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:40:17 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:40:17 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:40:17 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:17 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:17 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:17 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:17 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:17 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:17 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:17 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:17 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:17 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:18 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:40:18 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:40:18 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:40:18 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:40:18 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:40:18 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:40:20 rivo volumio[3129]: info: CoreCommandRouter::volumioNext Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::next Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::stop Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::stPlaybackTimer Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:40:20 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:20 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:20 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:20 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::serviceStop Jul 21 12:40:20 rivo volumio[3129]: info: CorePlayQueue::getTrack 10 Jul 21 12:40:20 rivo volumio[3129]: info: CoreCommandRouter::serviceStop Jul 21 12:40:20 rivo volumio[3129]: info: Spotify Stop Jul 21 12:40:20 rivo volumio[3129]: SPOTIFY: SPOTIFY STOP Jul 21 12:40:20 rivo volumio[3129]: SPOTIFY: {"status":"play","position":10,"title":"Mwaki","artist":"Zerb","album":"Mwaki (Major Lazer Remix)","albumart":"https://i.scdn.co/image/ab67616d0000b2731a6508c19c3bc140f707f319","uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","trackType":"spotify","codec":"ogg","seek":0,"duration":208,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":66,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 21 12:40:20 rivo volumio[3129]: info: Sending Spotify command to local API: /player/pause Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::play index undefined Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 21 12:40:20 rivo volumio[3129]: info: CorePlayQueue::getTrack 11 Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::startPlaybackTimer Jul 21 12:40:20 rivo volumio[3129]: info: CorePlayQueue::getTrack 11 Jul 21 12:40:20 rivo volumio[3129]: info: [1721558420420] ControllerSpotify::clearAddPlayTrack Jul 21 12:40:20 rivo volumio[3129]: info: Sending Spotify command with payload to local API: /player/play Jul 21 12:40:20 rivo volumio[3129]: info: CoreStateMachine::updateTrackBlock Jul 21 12:40:20 rivo volumio[3129]: info: CorePlayQueue::getTrackBlock Jul 21 12:40:20 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:20 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:20 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:20 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:20 rivo go-librespot[3808]: time="2024-07-21T12:40:20+02:00" level=debug msg="pause track at 4672ms" Jul 21 12:40:20 rivo go-librespot[3808]: time="2024-07-21T12:40:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=trace msg="emitting websocket event: paused" Jul 21 12:40:21 rivo volumio[3129]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:1YexFEloUaShjmXGE0iPR1","play_origin":"go-librespot"}} Jul 21 12:40:21 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:40:21 rivo volumio[3129]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:21 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:40:21 rivo volumio[3129]: info: CorePlayQueue::getTrack 11 Jul 21 12:40:21 rivo volumio[3129]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:21 rivo volumio[3129]: verbose: CURRENT POSITION 11 Jul 21 12:40:21 rivo volumio[3129]: info: CoreStateMachine::syncState stateService pause Jul 21 12:40:21 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:40:21 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:21 rivo volumio[3129]: info: CorePlayQueue::getTrack 11 Jul 21 12:40:21 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:21 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:21 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=debug msg="loading track spotify:track:75ckdfW23NPWGDMSjdUFBv (paused: false, position: 0ms)" Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=trace msg="emitting websocket event: will_play" Jul 21 12:40:21 rivo volumio[3129]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:75ckdfW23NPWGDMSjdUFBv","play_origin":"go-librespot"}} Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:75ckdfW23NPWGDMSjdUFBv" Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=debug msg="requested aes key for file 5427cf2876fb99deead33876f5bddac6c247f131, gid: 75ckdfW23NPWGDMSjdUFBv" Jul 21 12:40:21 rivo volumio[3129]: info: camilladsp spawned new process with pid 8216, instance 1, run: true Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=debug msg="fetched first chunk of 18, total size is 8978975 bytes" Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:21 rivo go-librespot[3808]: time="2024-07-21T12:40:21+02:00" level=info msg="loaded track \"Waiting For Tonight\" (uri: spotify:track:75ckdfW23NPWGDMSjdUFBv, paused: false, position: 0ms, duration: 198019ms)" Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:21 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:22 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:22 rivo go-librespot[3808]: time="2024-07-21T12:40:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:22 rivo go-librespot[3808]: time="2024-07-21T12:40:22+02:00" level=trace msg="emitting websocket event: metadata" Jul 21 12:40:22 rivo volumio[3129]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:75ckdfW23NPWGDMSjdUFBv","name":"Waiting For Tonight","artist_names":["FISHER","Jennifer Lopez"],"album_name":"Waiting For Tonight","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021bdabe7ca53bc0b39f43b5c0","position":0,"duration":198019,"release_date":"year:2024 month:5 day:3","track_number":1,"disc_number":1}} Jul 21 12:40:22 rivo go-librespot[3808]: time="2024-07-21T12:40:22+02:00" level=debug msg="fetched chunk 3/17, size: 524288" Jul 21 12:40:22 rivo go-librespot[3808]: time="2024-07-21T12:40:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 21 12:40:22 rivo go-librespot[3808]: time="2024-07-21T12:40:22+02:00" level=trace msg="emitting websocket event: playing" Jul 21 12:40:22 rivo volumio[3129]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:75ckdfW23NPWGDMSjdUFBv","play_origin":"go-librespot"}} Jul 21 12:40:22 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:40:22 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Waiting For Tonight","artist":"FISHER, Jennifer Lopez","album":"Waiting For Tonight","albumart":"https://i.scdn.co/image/ab67616d00001e021bdabe7ca53bc0b39f43b5c0","uri":"spotify:track:75ckdfW23NPWGDMSjdUFBv","trackType":"spotify","seek":0,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:22 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:40:22 rivo volumio[3129]: info: CorePlayQueue::getTrack 11 Jul 21 12:40:22 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Waiting For Tonight","artist":"FISHER, Jennifer Lopez","album":"Waiting For Tonight","albumart":"https://i.scdn.co/image/ab67616d00001e021bdabe7ca53bc0b39f43b5c0","uri":"spotify:track:75ckdfW23NPWGDMSjdUFBv","trackType":"spotify","seek":0,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:22 rivo volumio[3129]: verbose: CURRENT POSITION 11 Jul 21 12:40:22 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:40:22 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus stop Jul 21 12:40:22 rivo go-librespot[3808]: time="2024-07-21T12:40:22+02:00" level=debug msg="fetched chunk 1/17, size: 524288" Jul 21 12:40:22 rivo go-librespot[3808]: time="2024-07-21T12:40:22+02:00" level=debug msg="fetched chunk 2/17, size: 524288" Jul 21 12:40:22 rivo volumio[3129]: SPOTIFY: PUSH STATE SPOTIFY Jul 21 12:40:22 rivo volumio[3129]: SPOTIFY: {"status":"play","service":"spop","title":"Waiting For Tonight","artist":"FISHER, Jennifer Lopez","album":"Waiting For Tonight","albumart":"https://i.scdn.co/image/ab67616d00001e021bdabe7ca53bc0b39f43b5c0","uri":"spotify:track:75ckdfW23NPWGDMSjdUFBv","trackType":"spotify","seek":0,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:22 rivo volumio[3129]: info: CoreCommandRouter::servicePushState Jul 21 12:40:22 rivo volumio[3129]: info: CorePlayQueue::getTrack 11 Jul 21 12:40:22 rivo volumio[3129]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Waiting For Tonight","artist":"FISHER, Jennifer Lopez","album":"Waiting For Tonight","albumart":"https://i.scdn.co/image/ab67616d00001e021bdabe7ca53bc0b39f43b5c0","uri":"spotify:track:75ckdfW23NPWGDMSjdUFBv","trackType":"spotify","seek":0,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 21 12:40:22 rivo volumio[3129]: verbose: CURRENT POSITION 11 Jul 21 12:40:22 rivo volumio[3129]: info: CoreStateMachine::syncState stateService play Jul 21 12:40:22 rivo volumio[3129]: info: CoreStateMachine::syncState currentStatus play Jul 21 12:40:22 rivo volumio[3129]: info: Received an update from plugin. extracting info from payload Jul 21 12:40:22 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:22 rivo volumio[3129]: info: CorePlayQueue::getTrack 11 Jul 21 12:40:22 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 21 12:40:22 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:22 rivo volumio[3129]: info: CoreStateMachine::pushState Jul 21 12:40:22 rivo volumio[3129]: info: CorePlayQueue::getTrack 11 Jul 21 12:40:22 rivo volumio[3129]: info: CoreCommandRouter::volumioPushState Jul 21 12:40:22 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:22 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:22 rivo volumio[3129]: info: FusionDsp - volume level for loudness 66 gain applied 0.00 Jul 21 12:40:22 rivo volumio[3129]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 21 12:40:22 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:22 rivo volumio[3129]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jul 21 12:40:22 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:22 rivo volumio[3129]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jul 21 12:40:23 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:40:23 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:40:23 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:40:23 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:40:23 rivo volumio[3129]: info: Executing endpoint metavolumio Jul 21 12:40:23 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 21 12:40:27 rivo volumio[3129]: error: Failed request for metavolumio API Jul 21 12:40:28 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 21 12:40:28 rivo volumio[3129]: info: Preload queue cleared Jul 21 12:40:29 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 21 12:40:29 rivo volumio[3129]: info: Preload queue cleared Jul 21 12:40:30 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 21 12:40:30 rivo go-librespot[3808]: time="2024-07-21T12:40:30+02:00" level=debug msg="fetched chunk 4/17, size: 524288" Jul 21 12:40:31 rivo volumio[3129]: info: Preload queue cleared Jul 21 12:40:33 rivo volumio[3129]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 21 12:40:33 rivo volumio[3129]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 21 12:40:33 rivo volumio[3129]: TypeError: Cannot read property 'length' of undefined Jul 21 12:40:33 rivo volumio[3129]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jul 21 12:40:33 rivo volumio[3129]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jul 21 12:40:33 rivo volumio[3129]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jul 21 12:40:33 rivo volumio[3129]: at Parser.emit (events.js:400:28) Jul 21 12:40:33 rivo volumio[3129]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jul 21 12:40:33 rivo volumio[3129]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jul 21 12:40:33 rivo volumio[3129]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jul 21 12:40:33 rivo volumio[3129]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jul 21 12:40:33 rivo volumio[3129]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jul 21 12:40:33 rivo volumio[3129]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jul 21 12:40:33 rivo volumio[3129]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jul 21 12:40:33 rivo volumio[3129]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jul 21 12:40:33 rivo volumio[3129]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jul 21 12:40:33 rivo volumio[3129]: at IncomingMessage.emit (events.js:412:35) Jul 21 12:40:33 rivo volumio[3129]: at endReadableNT (internal/streams/readable.js:1333:12) Jul 21 12:40:33 rivo volumio[3129]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Jul 21 12:40:33 rivo volumio[3129]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 21 12:40:34 rivo sudo[8238]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-21 12:39 Jul 21 12:40:34 rivo sudo[8238]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 09:27:25 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="891b8adfc94c7cc44424972b60e8e09c"