-- Logs begin at Wed 2024-05-08 00:25:40 UTC, end at Wed 2024-05-08 05:26:51 UTC. -- May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=trace msg="emitting websocket event: will_play" May 08 05:25:00 volumio volumio[659]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","play_origin":"go-librespot"}} May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="selected format OGG_VORBIS_160 for spotify:track:4B3usQNwdXthj9zvlPpzTl" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="requested aes key for file bf6e6dbe5bad042f36ae47f30f876bc3ddd283ce, gid: 4B3usQNwdXthj9zvlPpzTl" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="fetched first chunk of 9, total size is 4495084 bytes" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=trace msg="seek to 0ms (diff: -593ms, samples: 0, bytes: 0)" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=info msg="loaded track \"Xana\" (uri: spotify:track:4B3usQNwdXthj9zvlPpzTl, paused: false, position: 0ms, duration: 268933ms)" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="vorbis: corrupt or missing data in bitstream" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="fetched chunk 2/8, size: 524288" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="fetched chunk 1/8, size: 524288" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=trace msg="emitting websocket event: metadata" May 08 05:25:00 volumio volumio[659]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","name":"Xana","artist_names":["Sakis Rouvas"],"album_name":"Aima Dakrya kai Idrotas","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02821cb9fa0e622e0fc11d46ae","position":0,"duration":268933,"release_date":"year:1994","track_number":3,"disc_number":1}} May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="fetched chunk 3/8, size: 524288" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:00 volumio go-librespot[13937]: time="2024-05-08T05:25:00Z" level=trace msg="emitting websocket event: playing" May 08 05:25:00 volumio volumio[659]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","play_origin":"go-librespot"}} May 08 05:25:00 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:00 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Xana","artist":"Sakis Rouvas","album":"Aima Dakrya kai Idrotas","albumart":"https://i.scdn.co/image/ab67616d00001e02821cb9fa0e622e0fc11d46ae","uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","trackType":"spotify","seek":0,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:00 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:00 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:00 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Xana","artist":"Sakis Rouvas","album":"Aima Dakrya kai Idrotas","albumart":"https://i.scdn.co/image/ab67616d00001e02821cb9fa0e622e0fc11d46ae","uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","trackType":"spotify","seek":0,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:00 volumio volumio[659]: verbose: CURRENT POSITION 7 May 08 05:25:00 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:25:00 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:25:00 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:00 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Xana","artist":"Sakis Rouvas","album":"Aima Dakrya kai Idrotas","albumart":"https://i.scdn.co/image/ab67616d00001e02821cb9fa0e622e0fc11d46ae","uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","trackType":"spotify","seek":0,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:00 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:00 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:00 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Xana","artist":"Sakis Rouvas","album":"Aima Dakrya kai Idrotas","albumart":"https://i.scdn.co/image/ab67616d00001e02821cb9fa0e622e0fc11d46ae","uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","trackType":"spotify","seek":0,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:00 volumio volumio[659]: verbose: CURRENT POSITION 7 May 08 05:25:00 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:25:00 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:25:00 volumio volumio[659]: info: Received an update from plugin. extracting info from payload May 08 05:25:00 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:00 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:00 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:00 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:00 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:00 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:00 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:04 volumio volumio[659]: info: CoreCommandRouter::volumioSeek May 08 05:25:04 volumio volumio[659]: info: CoreStateMachine::seek May 08 05:25:04 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:04 volumio volumio[659]: info: TRACKBLOCK {"uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","service":"spop","name":"Xana","artist":"Sakis Rouvas","album":"Aima Dakrya kai Idrotas","type":"song","duration":268,"albumart":"https://i.scdn.co/image/ab67616d0000b273821cb9fa0e622e0fc11d46ae","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify","channels":2} May 08 05:25:04 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:25:04 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:04 volumio volumio[659]: info: Spotify seek to: 58000 May 08 05:25:04 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/seek May 08 05:25:04 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:04 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:04 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:04 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:04 volumio go-librespot[13937]: time="2024-05-08T05:25:04Z" level=debug msg="seek track to 58000ms" May 08 05:25:04 volumio go-librespot[13937]: time="2024-05-08T05:25:04Z" level=trace msg="seek to 58000ms (diff: 33ms, samples: 2557800, bytes: 962836)" May 08 05:25:04 volumio go-librespot[13937]: time="2024-05-08T05:25:04Z" level=debug msg="fetched chunk 4/8, size: 524288" May 08 05:25:04 volumio go-librespot[13937]: time="2024-05-08T05:25:04Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:04 volumio go-librespot[13937]: time="2024-05-08T05:25:04Z" level=trace msg="emitting websocket event: seek" May 08 05:25:04 volumio volumio[659]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","position":58000,"duration":268933,"play_origin":"go-librespot"}} May 08 05:25:04 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:04 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Xana","artist":"Sakis Rouvas","album":"Aima Dakrya kai Idrotas","albumart":"https://i.scdn.co/image/ab67616d00001e02821cb9fa0e622e0fc11d46ae","uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","trackType":"spotify","seek":58000,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:04 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:04 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:04 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Xana","artist":"Sakis Rouvas","album":"Aima Dakrya kai Idrotas","albumart":"https://i.scdn.co/image/ab67616d00001e02821cb9fa0e622e0fc11d46ae","uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","trackType":"spotify","seek":58000,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:04 volumio volumio[659]: verbose: CURRENT POSITION 7 May 08 05:25:04 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:25:04 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:25:04 volumio volumio[659]: info: Received an update from plugin. extracting info from payload May 08 05:25:04 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:04 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:04 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:04 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:04 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:04 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:07 volumio volumio[659]: info: CoreCommandRouter::volumioNext May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::next May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::stop May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::stPlaybackTimer May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:25:07 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:07 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:07 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:07 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::serviceStop May 08 05:25:07 volumio volumio[659]: info: CorePlayQueue::getTrack 7 May 08 05:25:07 volumio volumio[659]: info: CoreCommandRouter::serviceStop May 08 05:25:07 volumio volumio[659]: info: Spotify Stop May 08 05:25:07 volumio volumio[659]: SPOTIFY: SPOTIFY STOP May 08 05:25:07 volumio volumio[659]: SPOTIFY: {"status":"play","position":7,"title":"Xana","artist":"Sakis Rouvas","album":"Aima Dakrya kai Idrotas","albumart":"https://i.scdn.co/image/ab67616d0000b273821cb9fa0e622e0fc11d46ae","uri":"spotify:track:4B3usQNwdXthj9zvlPpzTl","trackType":"spotify","codec":"ogg","seek":58000,"duration":268,"samplerate":"160 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 08 05:25:07 volumio volumio[659]: info: Sending Spotify command to local API: /player/pause May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::play index undefined May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:25:07 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:25:07 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:07 volumio volumio[659]: info: [1715145907305] ControllerSpotify::clearAddPlayTrack May 08 05:25:07 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/play May 08 05:25:07 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:25:07 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:25:07 volumio go-librespot[13937]: time="2024-05-08T05:25:07Z" level=debug msg="pause track at 61497ms" May 08 05:25:07 volumio go-librespot[13937]: time="2024-05-08T05:25:07Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:07 volumio go-librespot[13937]: time="2024-05-08T05:25:07Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" May 08 05:25:07 volumio go-librespot[13937]: time="2024-05-08T05:25:07Z" level=debug msg="loading track spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe (paused: false, position: 0ms)" May 08 05:25:07 volumio go-librespot[13937]: time="2024-05-08T05:25:07Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:07 volumio go-librespot[13937]: time="2024-05-08T05:25:07Z" level=trace msg="emitting websocket event: will_play" May 08 05:25:07 volumio volumio[659]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","play_origin":"go-librespot"}} May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="selected format OGG_VORBIS_160 for spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="requested aes key for file 8592cac3a5eaef9becd3a55b7c4caa4b21b9a2e5, gid: 1Fxi5jbp3c6Qvd2SsDpWfe" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="fetched first chunk of 10, total size is 5182840 bytes" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=trace msg="seek to 0ms (diff: -361ms, samples: 0, bytes: 0)" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=info msg="loaded track \"Mia Fora\" (uri: spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe, paused: false, position: 0ms, duration: 276480ms)" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="vorbis: corrupt or missing data in bitstream" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="fetched chunk 1/9, size: 524288" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="fetched chunk 2/9, size: 524288" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=trace msg="emitting websocket event: metadata" May 08 05:25:08 volumio volumio[659]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","name":"Mia Fora","artist_names":["Dimitris Korgialas","Katerina Moutsatsou"],"album_name":"As' Ta Dyskola Se Mena","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023a5d98c9db7ba4ec6ff979d9","position":0,"duration":276480,"release_date":"year:2004","track_number":6,"disc_number":1}} May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="fetched chunk 3/9, size: 524288" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=trace msg="emitting websocket event: paused" May 08 05:25:08 volumio volumio[659]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","play_origin":"go-librespot"}} May 08 05:25:08 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:08 volumio volumio[659]: SPOTIFY: {"status":"pause","service":"spop","title":"Mia Fora","artist":"Dimitris Korgialas, Katerina Moutsatsou","album":"As' Ta Dyskola Se Mena","albumart":"https://i.scdn.co/image/ab67616d00001e023a5d98c9db7ba4ec6ff979d9","uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:08 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:08 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:08 volumio volumio[659]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Mia Fora","artist":"Dimitris Korgialas, Katerina Moutsatsou","album":"As' Ta Dyskola Se Mena","albumart":"https://i.scdn.co/image/ab67616d00001e023a5d98c9db7ba4ec6ff979d9","uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:08 volumio volumio[659]: verbose: CURRENT POSITION 8 May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::syncState stateService pause May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:08 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:08 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:08 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:08 volumio go-librespot[13937]: time="2024-05-08T05:25:08Z" level=trace msg="emitting websocket event: playing" May 08 05:25:08 volumio volumio[659]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","play_origin":"go-librespot"}} May 08 05:25:08 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:08 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Mia Fora","artist":"Dimitris Korgialas, Katerina Moutsatsou","album":"As' Ta Dyskola Se Mena","albumart":"https://i.scdn.co/image/ab67616d00001e023a5d98c9db7ba4ec6ff979d9","uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:08 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:08 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:08 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Mia Fora","artist":"Dimitris Korgialas, Katerina Moutsatsou","album":"As' Ta Dyskola Se Mena","albumart":"https://i.scdn.co/image/ab67616d00001e023a5d98c9db7ba4ec6ff979d9","uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:08 volumio volumio[659]: verbose: CURRENT POSITION 8 May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:25:08 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:08 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Mia Fora","artist":"Dimitris Korgialas, Katerina Moutsatsou","album":"As' Ta Dyskola Se Mena","albumart":"https://i.scdn.co/image/ab67616d00001e023a5d98c9db7ba4ec6ff979d9","uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:08 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:08 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:08 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Mia Fora","artist":"Dimitris Korgialas, Katerina Moutsatsou","album":"As' Ta Dyskola Se Mena","albumart":"https://i.scdn.co/image/ab67616d00001e023a5d98c9db7ba4ec6ff979d9","uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","trackType":"spotify","seek":0,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:08 volumio volumio[659]: verbose: CURRENT POSITION 8 May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:25:08 volumio volumio[659]: info: Received an update from plugin. extracting info from payload May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:08 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:08 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:08 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:08 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:08 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:08 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:11 volumio volumio[659]: info: CoreCommandRouter::volumioNext May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::next May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::stop May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::stPlaybackTimer May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:25:11 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:11 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:11 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:11 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::serviceStop May 08 05:25:11 volumio volumio[659]: info: CorePlayQueue::getTrack 8 May 08 05:25:11 volumio volumio[659]: info: CoreCommandRouter::serviceStop May 08 05:25:11 volumio volumio[659]: info: Spotify Stop May 08 05:25:11 volumio volumio[659]: SPOTIFY: SPOTIFY STOP May 08 05:25:11 volumio volumio[659]: SPOTIFY: {"status":"play","position":8,"title":"Mia Fora","artist":"Dimitris Korgialas","album":"As' Ta Dyskola Se Mena","albumart":"https://i.scdn.co/image/ab67616d0000b2733a5d98c9db7ba4ec6ff979d9","uri":"spotify:track:1Fxi5jbp3c6Qvd2SsDpWfe","trackType":"spotify","codec":"ogg","seek":0,"duration":276,"samplerate":"160 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 08 05:25:11 volumio volumio[659]: info: Sending Spotify command to local API: /player/pause May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::play index undefined May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:25:11 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:25:11 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:11 volumio volumio[659]: info: [1715145911937] ControllerSpotify::clearAddPlayTrack May 08 05:25:11 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/play May 08 05:25:11 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:25:11 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:25:12 volumio go-librespot[13937]: time="2024-05-08T05:25:12Z" level=debug msg="pause track at 4524ms" May 08 05:25:12 volumio go-librespot[13937]: time="2024-05-08T05:25:12Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:12 volumio go-librespot[13937]: time="2024-05-08T05:25:12Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" May 08 05:25:12 volumio go-librespot[13937]: time="2024-05-08T05:25:12Z" level=debug msg="loading track spotify:track:3MjUtNVVq3C8Fn0MP3zhXa (paused: false, position: 0ms)" May 08 05:25:12 volumio go-librespot[13937]: time="2024-05-08T05:25:12Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:12 volumio go-librespot[13937]: time="2024-05-08T05:25:12Z" level=trace msg="emitting websocket event: will_play" May 08 05:25:12 volumio volumio[659]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","play_origin":"go-librespot"}} May 08 05:25:12 volumio go-librespot[13937]: time="2024-05-08T05:25:12Z" level=debug msg="selected format OGG_VORBIS_160 for spotify:track:3MjUtNVVq3C8Fn0MP3zhXa" May 08 05:25:12 volumio go-librespot[13937]: time="2024-05-08T05:25:12Z" level=debug msg="requested aes key for file 70b60f314a5d9a7ae1f562003d8a3064c157c1c6, gid: 3MjUtNVVq3C8Fn0MP3zhXa" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=debug msg="fetched first chunk of 8, total size is 3874228 bytes" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=trace msg="seek to 0ms (diff: -362ms, samples: 0, bytes: 0)" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=info msg="loaded track \"...Baby One More Time\" (uri: spotify:track:3MjUtNVVq3C8Fn0MP3zhXa, paused: false, position: 0ms, duration: 211066ms)" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=debug msg="vorbis: corrupt or missing data in bitstream" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=debug msg="fetched chunk 1/7, size: 524288" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=trace msg="emitting websocket event: metadata" May 08 05:25:13 volumio volumio[659]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","name":"...Baby One More Time","artist_names":["Britney Spears"],"album_name":"...Baby One More Time (Digital Deluxe Version)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e028e49866860c25afffe2f1a02","position":0,"duration":211066,"release_date":"year:1999 month:1 day:12","track_number":1,"disc_number":1}} May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=debug msg="fetched chunk 2/7, size: 524288" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=debug msg="fetched chunk 3/7, size: 524288" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=trace msg="emitting websocket event: paused" May 08 05:25:13 volumio volumio[659]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","play_origin":"go-librespot"}} May 08 05:25:13 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:13 volumio volumio[659]: SPOTIFY: {"status":"pause","service":"spop","title":"...Baby One More Time","artist":"Britney Spears","album":"...Baby One More Time (Digital Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e028e49866860c25afffe2f1a02","uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","trackType":"spotify","seek":0,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:13 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:13 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:13 volumio volumio[659]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"...Baby One More Time","artist":"Britney Spears","album":"...Baby One More Time (Digital Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e028e49866860c25afffe2f1a02","uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","trackType":"spotify","seek":0,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:13 volumio volumio[659]: verbose: CURRENT POSITION 9 May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::syncState stateService pause May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:13 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:13 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:13 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:13 volumio go-librespot[13937]: time="2024-05-08T05:25:13Z" level=trace msg="emitting websocket event: playing" May 08 05:25:13 volumio volumio[659]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","play_origin":"go-librespot"}} May 08 05:25:13 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:13 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"...Baby One More Time","artist":"Britney Spears","album":"...Baby One More Time (Digital Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e028e49866860c25afffe2f1a02","uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","trackType":"spotify","seek":0,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:13 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:13 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:13 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"...Baby One More Time","artist":"Britney Spears","album":"...Baby One More Time (Digital Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e028e49866860c25afffe2f1a02","uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","trackType":"spotify","seek":0,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:13 volumio volumio[659]: verbose: CURRENT POSITION 9 May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:25:13 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:13 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"...Baby One More Time","artist":"Britney Spears","album":"...Baby One More Time (Digital Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e028e49866860c25afffe2f1a02","uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","trackType":"spotify","seek":0,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:13 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:13 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:13 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"...Baby One More Time","artist":"Britney Spears","album":"...Baby One More Time (Digital Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d00001e028e49866860c25afffe2f1a02","uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","trackType":"spotify","seek":0,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:13 volumio volumio[659]: verbose: CURRENT POSITION 9 May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:25:13 volumio volumio[659]: info: Received an update from plugin. extracting info from payload May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:13 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:13 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:13 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:13 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:13 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:13 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:15 volumio volumio[659]: info: CoreCommandRouter::volumioNext May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::next May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::stop May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::stPlaybackTimer May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:25:15 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:15 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:15 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:15 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::serviceStop May 08 05:25:15 volumio volumio[659]: info: CorePlayQueue::getTrack 9 May 08 05:25:15 volumio volumio[659]: info: CoreCommandRouter::serviceStop May 08 05:25:15 volumio volumio[659]: info: Spotify Stop May 08 05:25:15 volumio volumio[659]: SPOTIFY: SPOTIFY STOP May 08 05:25:15 volumio volumio[659]: SPOTIFY: {"status":"play","position":9,"title":"...Baby One More Time","artist":"Britney Spears","album":"...Baby One More Time (Digital Deluxe Version)","albumart":"https://i.scdn.co/image/ab67616d0000b2738e49866860c25afffe2f1a02","uri":"spotify:track:3MjUtNVVq3C8Fn0MP3zhXa","trackType":"spotify","codec":"ogg","seek":0,"duration":211,"samplerate":"160 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 08 05:25:15 volumio volumio[659]: info: Sending Spotify command to local API: /player/pause May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::play index undefined May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:25:15 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:25:15 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:15 volumio volumio[659]: info: [1715145915050] ControllerSpotify::clearAddPlayTrack May 08 05:25:15 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/play May 08 05:25:15 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:25:15 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:25:15 volumio go-librespot[13937]: time="2024-05-08T05:25:15Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" May 08 05:25:15 volumio go-librespot[13937]: time="2024-05-08T05:25:15Z" level=debug msg="loading track spotify:track:0SwOBJu1iIkxZGbHQtaoOS (paused: false, position: 723ms)" May 08 05:25:15 volumio go-librespot[13937]: time="2024-05-08T05:25:15Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:15 volumio go-librespot[13937]: time="2024-05-08T05:25:15Z" level=trace msg="emitting websocket event: will_play" May 08 05:25:15 volumio volumio[659]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","play_origin":"go-librespot"}} May 08 05:25:15 volumio go-librespot[13937]: time="2024-05-08T05:25:15Z" level=debug msg="selected format OGG_VORBIS_160 for spotify:track:0SwOBJu1iIkxZGbHQtaoOS" May 08 05:25:15 volumio go-librespot[13937]: time="2024-05-08T05:25:15Z" level=debug msg="requested aes key for file ab95f23e790461272ce0d1ace9f29f83be06e29f, gid: 0SwOBJu1iIkxZGbHQtaoOS" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=debug msg="fetched first chunk of 8, total size is 4184692 bytes" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=trace msg="seek to 723ms (diff: 599ms, samples: 31884, bytes: 11976)" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=info msg="loaded track \"Oti Oneirevomoun - Live\" (uri: spotify:track:0SwOBJu1iIkxZGbHQtaoOS, paused: false, position: 723ms, duration: 208080ms)" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=debug msg="vorbis: corrupt or missing data in bitstream" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=debug msg="fetched chunk 2/7, size: 524288" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=trace msg="emitting websocket event: metadata" May 08 05:25:17 volumio volumio[659]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","name":"Oti Oneirevomoun - Live","artist_names":["Despina Vandi"],"album_name":"Live Apo To Lykavitto","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020460d2977fc250d21603b83a","position":723,"duration":208080,"release_date":"year:2003 month:1 day:1","track_number":19,"disc_number":1}} May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=debug msg="fetched chunk 3/7, size: 524288" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=debug msg="fetched chunk 1/7, size: 524288" May 08 05:25:17 volumio go-librespot[13937]: time="2024-05-08T05:25:17Z" level=debug msg="pause track at 1247ms" May 08 05:25:18 volumio go-librespot[13937]: time="2024-05-08T05:25:18Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:18 volumio go-librespot[13937]: time="2024-05-08T05:25:18Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:18 volumio go-librespot[13937]: time="2024-05-08T05:25:18Z" level=trace msg="emitting websocket event: playing" May 08 05:25:18 volumio volumio[659]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","play_origin":"go-librespot"}} May 08 05:25:18 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:18 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Oti Oneirevomoun - Live","artist":"Despina Vandi","album":"Live Apo To Lykavitto","albumart":"https://i.scdn.co/image/ab67616d00001e020460d2977fc250d21603b83a","uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","trackType":"spotify","seek":723,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:18 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:18 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:18 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Oti Oneirevomoun - Live","artist":"Despina Vandi","album":"Live Apo To Lykavitto","albumart":"https://i.scdn.co/image/ab67616d00001e020460d2977fc250d21603b83a","uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","trackType":"spotify","seek":723,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:18 volumio volumio[659]: verbose: CURRENT POSITION 10 May 08 05:25:18 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:25:18 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:25:18 volumio go-librespot[13937]: time="2024-05-08T05:25:18Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:18 volumio go-librespot[13937]: time="2024-05-08T05:25:18Z" level=trace msg="emitting websocket event: paused" May 08 05:25:18 volumio volumio[659]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","play_origin":"go-librespot"}} May 08 05:25:18 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:18 volumio volumio[659]: SPOTIFY: {"status":"pause","service":"spop","title":"Oti Oneirevomoun - Live","artist":"Despina Vandi","album":"Live Apo To Lykavitto","albumart":"https://i.scdn.co/image/ab67616d00001e020460d2977fc250d21603b83a","uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","trackType":"spotify","seek":723,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:18 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:18 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:18 volumio volumio[659]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Oti Oneirevomoun - Live","artist":"Despina Vandi","album":"Live Apo To Lykavitto","albumart":"https://i.scdn.co/image/ab67616d00001e020460d2977fc250d21603b83a","uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","trackType":"spotify","seek":723,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:18 volumio volumio[659]: verbose: CURRENT POSITION 10 May 08 05:25:18 volumio volumio[659]: info: CoreStateMachine::syncState stateService pause May 08 05:25:18 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:25:18 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:18 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:18 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:18 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:18 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:25:18 volumio volumio[659]: SPOTIFY: {"status":"pause","service":"spop","title":"Oti Oneirevomoun - Live","artist":"Despina Vandi","album":"Live Apo To Lykavitto","albumart":"https://i.scdn.co/image/ab67616d00001e020460d2977fc250d21603b83a","uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","trackType":"spotify","seek":723,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:18 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:25:18 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:18 volumio volumio[659]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Oti Oneirevomoun - Live","artist":"Despina Vandi","album":"Live Apo To Lykavitto","albumart":"https://i.scdn.co/image/ab67616d00001e020460d2977fc250d21603b83a","uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","trackType":"spotify","seek":723,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:25:18 volumio volumio[659]: verbose: CURRENT POSITION 10 May 08 05:25:18 volumio volumio[659]: info: CoreStateMachine::syncState stateService pause May 08 05:25:18 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:25:18 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:18 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:18 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:18 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:29 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 08 05:25:29 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 08 05:25:32 volumio go-librespot[13937]: time="2024-05-08T05:25:32Z" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" May 08 05:25:32 volumio volumio[659]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify May 08 05:25:32 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 08 05:25:32 volumio volumio[659]: info: Disabling plugin spop May 08 05:25:32 volumio volumio[659]: info: Done. May 08 05:25:32 volumio volumio[659]: info: Connection to go-librespot Websocket closed May 08 05:25:32 volumio sudo[14194]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service May 08 05:25:32 volumio sudo[14194]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 05:25:32 volumio systemd[1]: Stopping go-librespot Daemon... May 08 05:25:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM May 08 05:25:32 volumio systemd[1]: go-librespot-daemon.service: Succeeded. May 08 05:25:32 volumio systemd[1]: Stopped go-librespot Daemon. May 08 05:25:32 volumio sudo[14194]: pam_unix(sudo:session): session closed for user root May 08 05:25:33 volumio volumio[659]: info: Enabling plugin spop May 08 05:25:33 volumio volumio[659]: info: Loading plugin "spop"... May 08 05:25:33 volumio volumio[659]: info: PLUGIN START: spop May 08 05:25:33 volumio volumio[659]: info: Creating Spotify config file May 08 05:25:33 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 08 05:25:33 volumio volumio[659]: info: Done. May 08 05:25:33 volumio volumio[659]: info: Spotify config file written May 08 05:25:33 volumio sudo[14197]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 08 05:25:33 volumio sudo[14197]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 05:25:33 volumio go-librespot[14199]: Librespot-go daemon starting... May 08 05:25:33 volumio systemd[1]: Started go-librespot Daemon. May 08 05:25:33 volumio sudo[14197]: pam_unix(sudo:session): session closed for user root May 08 05:25:33 volumio go-librespot[14199]: time="2024-05-08T05:25:33Z" level=info msg="generated new device id: 41520f59afc98e788481054d04d728fc38193273" May 08 05:25:33 volumio go-librespot[14199]: time="2024-05-08T05:25:33Z" level=debug msg="stored credentials found for 31qbzhnzo4np7v7hfauhlr6mteau" May 08 05:25:33 volumio go-librespot[14199]: time="2024-05-08T05:25:33Z" level=debug msg="obtained new client token: AAAUx5kv3c/zv9IUSFGXW8Nzk7StPCMJgy8Kd9w5cE1TfzaKMrGoxiX5BGGcubJUwCGroRMc0lFqRFRmeToxBBLLFBMpUqGufjLiHAMZIAYZRp4aXi9q2GpcfhRwMY5iphRnrWr0qZgzbAFT4wcJ7GvybfouNuSlvU6ehjEDvkRsvpgXvIQCcqvwuUpyRKnzDoCrQExtiPiZTKMgk8jkPrKKJ+VLaoAmRAS4u+HhyXj2ktoZfiIzSDrXZquNCA==" May 08 05:25:33 volumio go-librespot[14199]: time="2024-05-08T05:25:33Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 08 05:25:33 volumio volumio[659]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 08 05:25:33 volumio volumio[659]: SPOTIFY: BQD5Z0bWvrpJFA_R8TjHKVY6P-MOnnRIPokyvNIhIswrRHhO5ltuKDrNd9L9T_ht8U_aED3bHPQJ8rDA-m59dxvHau6ZYkF6ZHbN91yFDWOGp55lMuhwo75GXHayLHvabV2qalu1JPvcrFRLzNXbj9dfRlc_dvJWdMBTSaf-dkAAzIysyl1ChmZPc_yEdtILigW-8pFlG1QHvVLZozAlcRzTrFe_x9tXmlBv_ITrTHZDaqox_utyGnER_GX4-Pk9bqE4O4k May 08 05:25:33 volumio volumio[659]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 08 05:25:33 volumio volumio[659]: info: New Spotify access token = BQD5Z0bWvrpJFA_R8TjHKVY6P-MOnnRIPokyvNIhIswrRHhO5ltuKDrNd9L9T_ht8U_aED3bHPQJ8rDA-m59dxvHau6ZYkF6ZHbN91yFDWOGp55lMuhwo75GXHayLHvabV2qalu1JPvcrFRLzNXbj9dfRlc_dvJWdMBTSaf-dkAAzIysyl1ChmZPc_yEdtILigW-8pFlG1QHvVLZozAlcRzTrFe_x9tXmlBv_ITrTHZDaqox_utyGnER_GX4-Pk9bqE4O4k May 08 05:25:33 volumio volumio[659]: info: Spotify credentials grant success - running version from March 24, 2019 May 08 05:25:33 volumio go-librespot[14199]: time="2024-05-08T05:25:33Z" level=debug msg="completed keyexchange" May 08 05:25:33 volumio volumio[659]: SPOTIFY: User informations: {"display_name":"Mathioskompos","external_urls":{"spotify":"https://open.spotify.com/user/31qbzhnzo4np7v7hfauhlr6mteau"},"href":"https://api.spotify.com/v1/users/31qbzhnzo4np7v7hfauhlr6mteau","id":"31qbzhnzo4np7v7hfauhlr6mteau","images":[],"type":"user","uri":"spotify:user:31qbzhnzo4np7v7hfauhlr6mteau","followers":{"href":null,"total":0},"country":"GR","product":"free","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"mathioskompos@gmail.com"} May 08 05:25:33 volumio volumio[659]: info: Spotify Successfully logged in May 08 05:25:33 volumio volumio[659]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 08 05:25:33 volumio volumio[659]: info: [1715145933596] CoreMusicLibrary::Adding element Spotify May 08 05:25:33 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 08 05:25:33 volumio volumio[659]: Cannot find translation for source Spotify May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="completed challenge" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="authenticated as 31qbzhnzo4np7v7hfauhlr6mteau" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="authenticated as 31qbzhnzo4np7v7hfauhlr6mteau" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="dealer connection opened" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="received connection id: Y2UyZDAzMjgtNDQ1Zi00NWYyLWEyYTYtNmQyYzA0NjRmYWY4K2RlYWxlcit0Y3A6Ly9nZXcxLWRlYWxlci1hLXY2ZGMuZ2V3MS5zcG90aWZ5Lm5ldDo1NzAwKzBEQkZGMDk0RDMwNzlEN0QwM0I4OEUwMzk2RUU4NjQzQUI2NTFBQjU2OTdENEQzRTM0MTZENkQ4RDJGMTdENjY=" May 08 05:25:34 volumio go-librespot[14199]: time="2024-05-08T05:25:34Z" level=debug msg="put connect state because NEW_DEVICE" May 08 05:25:35 volumio volumio[659]: info: CoreCommandRouter::volumioGetState May 08 05:25:35 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:36 volumio volumio[659]: info: go-librespot daemon successfully initialized May 08 05:25:36 volumio volumio[659]: info: CoreCommandRouter::volumioNext May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::next May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::stop May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::stPlaybackTimer May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:25:36 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:25:36 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:36 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:25:36 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::serviceStop May 08 05:25:36 volumio volumio[659]: info: CorePlayQueue::getTrack 10 May 08 05:25:36 volumio volumio[659]: info: CoreCommandRouter::serviceStop May 08 05:25:36 volumio volumio[659]: info: Spotify Stop May 08 05:25:36 volumio volumio[659]: SPOTIFY: SPOTIFY STOP May 08 05:25:36 volumio volumio[659]: SPOTIFY: {"status":"play","position":10,"title":"Oti Oneirevomoun - Live","artist":"Despina Vandi","album":"Live Apo To Lykavitto","albumart":"https://i.scdn.co/image/ab67616d0000b2730460d2977fc250d21603b83a","uri":"spotify:track:0SwOBJu1iIkxZGbHQtaoOS","trackType":"spotify","codec":"ogg","seek":1065,"duration":208,"samplerate":"160 kbps","bitdepth":"16 bit","random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 08 05:25:36 volumio volumio[659]: info: Sending Spotify command to local API: /player/pause May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::play index undefined May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:25:36 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:25:36 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:25:36 volumio volumio[659]: info: [1715145936797] ControllerSpotify::clearAddPlayTrack May 08 05:25:36 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/play May 08 05:25:36 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:25:36 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:25:36 volumio go-librespot[14199]: time="2024-05-08T05:25:36Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" May 08 05:25:36 volumio go-librespot[14199]: time="2024-05-08T05:25:36Z" level=debug msg="loading track spotify:track:0fxJH14Cwri9aGddVjq51U (paused: false, position: 0ms)" May 08 05:25:36 volumio go-librespot[14199]: time="2024-05-08T05:25:36Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:36 volumio go-librespot[14199]: time="2024-05-08T05:25:36Z" level=trace msg="emitting websocket event: will_play" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="selected format OGG_VORBIS_160 for spotify:track:0fxJH14Cwri9aGddVjq51U" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="requested aes key for file 89c706e498cf1024fbd161ea511fa9e045f9a5c2, gid: 0fxJH14Cwri9aGddVjq51U" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="fetched first chunk of 7, total size is 3608728 bytes" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=trace msg="seek to 0ms (diff: -965ms, samples: 0, bytes: 0)" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=info msg="loaded track \"M' Aresei Na Mi Leo Polla - Live\" (uri: spotify:track:0fxJH14Cwri9aGddVjq51U, paused: false, position: 0ms, duration: 212826ms)" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="vorbis: corrupt or missing data in bitstream" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="fetched chunk 1/6, size: 524288" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=trace msg="emitting websocket event: metadata" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="fetched chunk 2/6, size: 524288" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=trace msg="emitting websocket event: playing" May 08 05:25:37 volumio go-librespot[14199]: time="2024-05-08T05:25:37Z" level=debug msg="fetched chunk 3/6, size: 524288" May 08 05:25:39 volumio volumio[659]: info: Initializing connection to go-librespot Websocket May 08 05:25:39 volumio go-librespot[14199]: time="2024-05-08T05:25:39Z" level=debug msg="new websocket client" May 08 05:25:39 volumio volumio[659]: info: Connection to go-librespot Websocket established May 08 05:25:42 volumio volumio[659]: info: Getting Spotify volume May 08 05:25:42 volumio volumio[659]: info: Spotify volume: 100 May 08 05:25:42 volumio volumio[659]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 May 08 05:25:42 volumio volumio[659]: info: CoreCommandRouter::volumioGetState May 08 05:25:42 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:11 volumio go-librespot[14199]: time="2024-05-08T05:26:11Z" level=debug msg="fetched chunk 4/6, size: 524288" May 08 05:26:17 volumio volumio[659]: info: CoreCommandRouter::volumioSeek May 08 05:26:17 volumio volumio[659]: info: CoreStateMachine::seek May 08 05:26:17 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:17 volumio volumio[659]: info: TRACKBLOCK {"uri":"spotify:track:0fxJH14Cwri9aGddVjq51U","service":"spop","name":"M' Aresei Na Mi Leo Polla - Live","artist":"Ypogeia Revmata","album":"M' Aresei Na Mi Leo Polla (Live Sto Theatro Vrahon)","type":"song","duration":212,"albumart":"https://i.scdn.co/image/ab67616d0000b273ecb26ed9f56dbac90fadad45","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"} May 08 05:26:17 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:26:17 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:17 volumio volumio[659]: info: Spotify seek to: 60000 May 08 05:26:17 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/seek May 08 05:26:17 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:17 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:17 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:17 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:17 volumio go-librespot[14199]: time="2024-05-08T05:26:17Z" level=debug msg="seek track to 60000ms" May 08 05:26:17 volumio go-librespot[14199]: time="2024-05-08T05:26:17Z" level=trace msg="seek to 60000ms (diff: 260ms, samples: 2646000, bytes: 895151)" May 08 05:26:17 volumio go-librespot[14199]: time="2024-05-08T05:26:17Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:17 volumio go-librespot[14199]: time="2024-05-08T05:26:17Z" level=trace msg="emitting websocket event: seek" May 08 05:26:17 volumio volumio[659]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:0fxJH14Cwri9aGddVjq51U","position":60000,"duration":212826,"play_origin":"go-librespot"}} May 08 05:26:17 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:26:17 volumio volumio[659]: 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":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:17 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:26:17 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:17 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:17 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:17 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:17 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:17 volumio volumio[659]: 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":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:17 volumio volumio[659]: verbose: CURRENT POSITION 11 May 08 05:26:17 volumio volumio[659]: info: CoreStateMachine::syncState stateService stop May 08 05:26:17 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:26:17 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:17 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:17 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:17 volumio volumio[659]: info: No code May 08 05:26:17 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:17 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:17 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:20 volumio volumio[659]: info: CoreCommandRouter::volumioSeek May 08 05:26:20 volumio volumio[659]: info: CoreStateMachine::seek May 08 05:26:20 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:20 volumio volumio[659]: info: TRACKBLOCK {"uri":"spotify:track:0fxJH14Cwri9aGddVjq51U","service":"spop","name":"M' Aresei Na Mi Leo Polla - Live","artist":"Ypogeia Revmata","album":"M' Aresei Na Mi Leo Polla (Live Sto Theatro Vrahon)","type":"song","duration":212,"albumart":"https://i.scdn.co/image/ab67616d0000b273ecb26ed9f56dbac90fadad45","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"} May 08 05:26:20 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:26:20 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:20 volumio volumio[659]: info: Spotify seek to: 92000 May 08 05:26:20 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/seek May 08 05:26:20 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:20 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:20 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:20 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:20 volumio go-librespot[14199]: time="2024-05-08T05:26:20Z" level=debug msg="seek track to 92000ms" May 08 05:26:20 volumio go-librespot[14199]: time="2024-05-08T05:26:20Z" level=trace msg="seek to 92000ms (diff: 179ms, samples: 4057200, bytes: 1416017)" May 08 05:26:21 volumio go-librespot[14199]: time="2024-05-08T05:26:21Z" level=debug msg="fetched chunk 5/6, size: 524288" May 08 05:26:21 volumio go-librespot[14199]: time="2024-05-08T05:26:21Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:21 volumio go-librespot[14199]: time="2024-05-08T05:26:21Z" level=trace msg="emitting websocket event: seek" May 08 05:26:21 volumio volumio[659]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:0fxJH14Cwri9aGddVjq51U","position":92000,"duration":212826,"play_origin":"go-librespot"}} May 08 05:26:21 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:26:21 volumio volumio[659]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":92000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:21 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:26:21 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:21 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:21 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:21 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:21 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:21 volumio volumio[659]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":92000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:21 volumio volumio[659]: verbose: CURRENT POSITION 11 May 08 05:26:21 volumio volumio[659]: info: CoreStateMachine::syncState stateService stop May 08 05:26:21 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:26:21 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:21 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:21 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:21 volumio volumio[659]: info: No code May 08 05:26:21 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:21 volumio volumio[659]: info: CorePlayQueue::getTrack 11 May 08 05:26:21 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:26 volumio volumio[659]: info: CoreCommandRouter::volumioNext May 08 05:26:26 volumio volumio[659]: info: CoreStateMachine::next May 08 05:26:26 volumio volumio[659]: info: CoreStateMachine::stop May 08 05:26:26 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:26:26 volumio volumio[659]: info: CoreStateMachine::play index undefined May 08 05:26:26 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:26:26 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:26 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:26:26 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:26 volumio volumio[659]: info: [1715145986048] ControllerSpotify::clearAddPlayTrack May 08 05:26:26 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/play May 08 05:26:26 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:26:26 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:26:26 volumio go-librespot[14199]: time="2024-05-08T05:26:26Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" May 08 05:26:26 volumio go-librespot[14199]: time="2024-05-08T05:26:26Z" level=debug msg="loading track spotify:track:25FTMokYEbEWHEdss5JLZS (paused: false, position: 595ms)" May 08 05:26:26 volumio go-librespot[14199]: time="2024-05-08T05:26:26Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:26 volumio go-librespot[14199]: time="2024-05-08T05:26:26Z" level=trace msg="emitting websocket event: will_play" May 08 05:26:26 volumio volumio[659]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","play_origin":"go-librespot"}} May 08 05:26:26 volumio go-librespot[14199]: time="2024-05-08T05:26:26Z" level=debug msg="selected format OGG_VORBIS_160 for spotify:track:25FTMokYEbEWHEdss5JLZS" May 08 05:26:26 volumio go-librespot[14199]: time="2024-05-08T05:26:26Z" level=debug msg="requested aes key for file ccfe1382da118ed0896c1e98b7180ec39216a8ef, gid: 25FTMokYEbEWHEdss5JLZS" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=debug msg="fetched first chunk of 10, total size is 4883784 bytes" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=trace msg="seek to 595ms (diff: 417ms, samples: 26239, bytes: 0)" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=info msg="loaded track \"Teenage Dirtbag\" (uri: spotify:track:25FTMokYEbEWHEdss5JLZS, paused: false, position: 595ms, duration: 241666ms)" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=debug msg="vorbis: corrupt or missing data in bitstream" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=debug msg="fetched chunk 1/9, size: 524288" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=trace msg="emitting websocket event: metadata" May 08 05:26:27 volumio volumio[659]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","name":"Teenage Dirtbag","artist_names":["Wheatus"],"album_name":"Wheatus","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020a3740efa638f10f14fabc46","position":595,"duration":241666,"release_date":"year:1999 month:2 day:15","track_number":3,"disc_number":1}} May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=debug msg="fetched chunk 2/9, size: 524288" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=trace msg="emitting websocket event: playing" May 08 05:26:27 volumio volumio[659]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","play_origin":"go-librespot"}} May 08 05:26:27 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:26:27 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Teenage Dirtbag","artist":"Wheatus","album":"Wheatus","albumart":"https://i.scdn.co/image/ab67616d00001e020a3740efa638f10f14fabc46","uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","trackType":"spotify","seek":595,"duration":241,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:27 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:26:27 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:27 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Teenage Dirtbag","artist":"Wheatus","album":"Wheatus","albumart":"https://i.scdn.co/image/ab67616d00001e020a3740efa638f10f14fabc46","uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","trackType":"spotify","seek":595,"duration":241,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:27 volumio volumio[659]: verbose: CURRENT POSITION 12 May 08 05:26:27 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:26:27 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:26:27 volumio go-librespot[14199]: time="2024-05-08T05:26:27Z" level=debug msg="fetched chunk 3/9, size: 524288" May 08 05:26:27 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:26:27 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Teenage Dirtbag","artist":"Wheatus","album":"Wheatus","albumart":"https://i.scdn.co/image/ab67616d00001e020a3740efa638f10f14fabc46","uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","trackType":"spotify","seek":595,"duration":241,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:27 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:26:27 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:27 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Teenage Dirtbag","artist":"Wheatus","album":"Wheatus","albumart":"https://i.scdn.co/image/ab67616d00001e020a3740efa638f10f14fabc46","uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","trackType":"spotify","seek":595,"duration":241,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:27 volumio volumio[659]: verbose: CURRENT POSITION 12 May 08 05:26:27 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:26:27 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:26:27 volumio volumio[659]: info: Received an update from plugin. extracting info from payload May 08 05:26:27 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:27 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:27 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:27 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:27 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:27 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:27 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:30 volumio volumio[659]: info: CoreCommandRouter::volumioSeek May 08 05:26:30 volumio volumio[659]: info: CoreStateMachine::seek May 08 05:26:30 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:30 volumio volumio[659]: info: TRACKBLOCK {"uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","service":"spop","name":"Teenage Dirtbag","artist":"Wheatus","album":"Wheatus","type":"song","duration":241,"albumart":"https://i.scdn.co/image/ab67616d0000b2730a3740efa638f10f14fabc46","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify","channels":2} May 08 05:26:30 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:26:30 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:30 volumio volumio[659]: info: Spotify seek to: 53000 May 08 05:26:30 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/seek May 08 05:26:30 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:30 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:30 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:30 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:30 volumio go-librespot[14199]: time="2024-05-08T05:26:30Z" level=debug msg="seek track to 53000ms" May 08 05:26:30 volumio go-librespot[14199]: time="2024-05-08T05:26:30Z" level=trace msg="seek to 53000ms (diff: 284ms, samples: 2337300, bytes: 1054729)" May 08 05:26:30 volumio go-librespot[14199]: time="2024-05-08T05:26:30Z" level=debug msg="fetched chunk 5/9, size: 524288" May 08 05:26:30 volumio go-librespot[14199]: time="2024-05-08T05:26:30Z" level=debug msg="fetched chunk 4/9, size: 524288" May 08 05:26:30 volumio go-librespot[14199]: time="2024-05-08T05:26:30Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:30 volumio go-librespot[14199]: time="2024-05-08T05:26:30Z" level=trace msg="emitting websocket event: seek" May 08 05:26:30 volumio volumio[659]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","position":53000,"duration":241666,"play_origin":"go-librespot"}} May 08 05:26:30 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:26:30 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Teenage Dirtbag","artist":"Wheatus","album":"Wheatus","albumart":"https://i.scdn.co/image/ab67616d00001e020a3740efa638f10f14fabc46","uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","trackType":"spotify","seek":53000,"duration":241,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:30 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:26:30 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:30 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Teenage Dirtbag","artist":"Wheatus","album":"Wheatus","albumart":"https://i.scdn.co/image/ab67616d00001e020a3740efa638f10f14fabc46","uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","trackType":"spotify","seek":53000,"duration":241,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:30 volumio volumio[659]: verbose: CURRENT POSITION 12 May 08 05:26:30 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:26:30 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:26:30 volumio volumio[659]: info: Received an update from plugin. extracting info from payload May 08 05:26:30 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:30 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:30 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:30 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:30 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:30 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:33 volumio volumio[659]: info: CoreCommandRouter::volumioNext May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::next May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::stop May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::stPlaybackTimer May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:26:33 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:33 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:33 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:33 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::serviceStop May 08 05:26:33 volumio volumio[659]: info: CorePlayQueue::getTrack 12 May 08 05:26:33 volumio volumio[659]: info: CoreCommandRouter::serviceStop May 08 05:26:33 volumio volumio[659]: info: Spotify Stop May 08 05:26:33 volumio volumio[659]: SPOTIFY: SPOTIFY STOP May 08 05:26:33 volumio volumio[659]: SPOTIFY: {"status":"play","position":12,"title":"Teenage Dirtbag","artist":"Wheatus","album":"Wheatus","albumart":"https://i.scdn.co/image/ab67616d0000b2730a3740efa638f10f14fabc46","uri":"spotify:track:25FTMokYEbEWHEdss5JLZS","trackType":"spotify","codec":"ogg","seek":53000,"duration":241,"samplerate":"160 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 08 05:26:33 volumio volumio[659]: info: Sending Spotify command to local API: /player/pause May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::play index undefined May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:26:33 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::startPlaybackTimer May 08 05:26:33 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:33 volumio volumio[659]: info: [1715145993094] ControllerSpotify::clearAddPlayTrack May 08 05:26:33 volumio volumio[659]: info: Sending Spotify command with payload to local API: /player/play May 08 05:26:33 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:26:33 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:26:33 volumio go-librespot[14199]: time="2024-05-08T05:26:33Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" May 08 05:26:33 volumio go-librespot[14199]: time="2024-05-08T05:26:33Z" level=debug msg="loading track spotify:track:4SyhX0l8uaKHbSlnrcKu79 (paused: false, position: 595ms)" May 08 05:26:33 volumio go-librespot[14199]: time="2024-05-08T05:26:33Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:33 volumio go-librespot[14199]: time="2024-05-08T05:26:33Z" level=trace msg="emitting websocket event: will_play" May 08 05:26:33 volumio volumio[659]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","play_origin":"go-librespot"}} May 08 05:26:33 volumio go-librespot[14199]: time="2024-05-08T05:26:33Z" level=debug msg="selected format OGG_VORBIS_160 for spotify:track:4SyhX0l8uaKHbSlnrcKu79" May 08 05:26:33 volumio go-librespot[14199]: time="2024-05-08T05:26:33Z" level=debug msg="requested aes key for file fd31b77f5004c2369cbc809df331028960587408, gid: 4SyhX0l8uaKHbSlnrcKu79" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="fetched first chunk of 10, total size is 4993724 bytes" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=trace msg="seek to 595ms (diff: -545ms, samples: 26239, bytes: 0)" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=info msg="loaded track \"Ekdromi\" (uri: spotify:track:4SyhX0l8uaKHbSlnrcKu79, paused: false, position: 595ms, duration: 237200ms)" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="vorbis: corrupt or missing data in bitstream" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="fetched chunk 2/9, size: 524288" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="fetched chunk 1/9, size: 524288" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=trace msg="emitting websocket event: metadata" May 08 05:26:34 volumio volumio[659]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","name":"Ekdromi","artist_names":["Michalis Hatzigiannis"],"album_name":"Kryfo Fili","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0256b935541db5ac6e71ec5a49","position":595,"duration":237200,"release_date":"year:2002","track_number":8,"disc_number":1}} May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="fetched chunk 3/9, size: 524288" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="pause track at 1042ms" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=trace msg="emitting websocket event: playing" May 08 05:26:34 volumio volumio[659]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","play_origin":"go-librespot"}} May 08 05:26:34 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:26:34 volumio volumio[659]: SPOTIFY: {"status":"play","service":"spop","title":"Ekdromi","artist":"Michalis Hatzigiannis","album":"Kryfo Fili","albumart":"https://i.scdn.co/image/ab67616d00001e0256b935541db5ac6e71ec5a49","uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","trackType":"spotify","seek":595,"duration":237,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:34 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:26:34 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:34 volumio volumio[659]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Ekdromi","artist":"Michalis Hatzigiannis","album":"Kryfo Fili","albumart":"https://i.scdn.co/image/ab67616d00001e0256b935541db5ac6e71ec5a49","uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","trackType":"spotify","seek":595,"duration":237,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:34 volumio volumio[659]: verbose: CURRENT POSITION 13 May 08 05:26:34 volumio volumio[659]: info: CoreStateMachine::syncState stateService play May 08 05:26:34 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus stop May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 08 05:26:34 volumio go-librespot[14199]: time="2024-05-08T05:26:34Z" level=trace msg="emitting websocket event: paused" May 08 05:26:34 volumio volumio[659]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","play_origin":"go-librespot"}} May 08 05:26:34 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:26:34 volumio volumio[659]: SPOTIFY: {"status":"pause","service":"spop","title":"Ekdromi","artist":"Michalis Hatzigiannis","album":"Kryfo Fili","albumart":"https://i.scdn.co/image/ab67616d00001e0256b935541db5ac6e71ec5a49","uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","trackType":"spotify","seek":595,"duration":237,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:34 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:26:34 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:34 volumio volumio[659]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Ekdromi","artist":"Michalis Hatzigiannis","album":"Kryfo Fili","albumart":"https://i.scdn.co/image/ab67616d00001e0256b935541db5ac6e71ec5a49","uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","trackType":"spotify","seek":595,"duration":237,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:34 volumio volumio[659]: verbose: CURRENT POSITION 13 May 08 05:26:34 volumio volumio[659]: info: CoreStateMachine::syncState stateService pause May 08 05:26:34 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:26:34 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:34 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:34 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:34 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:35 volumio volumio[659]: SPOTIFY: PUSH STATE SPOTIFY May 08 05:26:35 volumio volumio[659]: SPOTIFY: {"status":"pause","service":"spop","title":"Ekdromi","artist":"Michalis Hatzigiannis","album":"Kryfo Fili","albumart":"https://i.scdn.co/image/ab67616d00001e0256b935541db5ac6e71ec5a49","uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","trackType":"spotify","seek":595,"duration":237,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:35 volumio volumio[659]: info: CoreCommandRouter::servicePushState May 08 05:26:35 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:35 volumio volumio[659]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Ekdromi","artist":"Michalis Hatzigiannis","album":"Kryfo Fili","albumart":"https://i.scdn.co/image/ab67616d00001e0256b935541db5ac6e71ec5a49","uri":"spotify:track:4SyhX0l8uaKHbSlnrcKu79","trackType":"spotify","seek":595,"duration":237,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 08 05:26:35 volumio volumio[659]: verbose: CURRENT POSITION 13 May 08 05:26:35 volumio volumio[659]: info: CoreStateMachine::syncState stateService pause May 08 05:26:35 volumio volumio[659]: info: CoreStateMachine::syncState currentStatus play May 08 05:26:35 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:35 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:35 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:35 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:40 volumio volumio[659]: info: CoreCommandRouter::volumioGetState May 08 05:26:40 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:43 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 08 05:26:43 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 08 05:26:46 volumio go-librespot[14199]: time="2024-05-08T05:26:46Z" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" May 08 05:26:46 volumio volumio[659]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify May 08 05:26:46 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 08 05:26:46 volumio volumio[659]: info: Disabling plugin spop May 08 05:26:46 volumio volumio[659]: info: Done. May 08 05:26:46 volumio volumio[659]: info: Connection to go-librespot Websocket closed May 08 05:26:46 volumio sudo[14250]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service May 08 05:26:46 volumio sudo[14250]: pam_unix(sudo:session): session opened for user root by (uid=0) May 08 05:26:46 volumio systemd[1]: Stopping go-librespot Daemon... May 08 05:26:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM May 08 05:26:46 volumio systemd[1]: go-librespot-daemon.service: Succeeded. May 08 05:26:46 volumio systemd[1]: Stopped go-librespot Daemon. May 08 05:26:46 volumio sudo[14250]: pam_unix(sudo:session): session closed for user root May 08 05:26:49 volumio volumio[659]: info: CoreCommandRouter::volumioGetState May 08 05:26:49 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:51 volumio volumio[659]: info: CoreCommandRouter::volumioNext May 08 05:26:51 volumio volumio[659]: info: CoreStateMachine::next May 08 05:26:51 volumio volumio[659]: info: CoreStateMachine::stop May 08 05:26:51 volumio volumio[659]: info: CoreStateMachine::setConsumeUpdateService undefined May 08 05:26:51 volumio volumio[659]: info: CoreStateMachine::stPlaybackTimer May 08 05:26:51 volumio volumio[659]: info: CoreStateMachine::updateTrackBlock May 08 05:26:51 volumio volumio[659]: info: CorePlayQueue::getTrackBlock May 08 05:26:51 volumio volumio[659]: info: CoreStateMachine::pushState May 08 05:26:51 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:51 volumio volumio[659]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 08 05:26:51 volumio volumio[659]: info: CoreCommandRouter::volumioPushState May 08 05:26:51 volumio volumio[659]: info: CoreStateMachine::serviceStop May 08 05:26:51 volumio volumio[659]: info: CorePlayQueue::getTrack 13 May 08 05:26:51 volumio volumio[659]: info: CoreCommandRouter::serviceStop May 08 05:26:51 volumio volumio[659]: error: WARNING: No stop method for service spop May 08 05:26:51 volumio volumio[659]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 08 05:26:51 volumio volumio[659]: TypeError: Cannot read property 'then' of undefined May 08 05:26:51 volumio volumio[659]: at CoreStateMachine.next (/volumio/app/statemachine.js:1167:9) May 08 05:26:51 volumio volumio[659]: at CoreCommandRouter.volumioNext (/volumio/app/index.js:101:28) May 08 05:26:51 volumio volumio[659]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:250:26) May 08 05:26:51 volumio volumio[659]: at Socket.emit (events.js:400:28) May 08 05:26:51 volumio volumio[659]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 May 08 05:26:51 volumio volumio[659]: at processTicksAndRejections (internal/process/task_queues.js:77:11) May 08 05:26:51 volumio volumio[659]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 08 05:26:51 volumio sudo[14261]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-08 05:25 May 08 05:26:51 volumio sudo[14261]: 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="e7445fab547cd22e23d9bef72406cfb610bc1d7d" VOLUMIO_FE_VERSION="5d5e99f8f803b3ec5fc5e8ca13bb4023600f3eee" VOLUMIO_FE3_VERSION="a6ae210575eae1ff43f06ab71e1cd17576840623" VOLUMIO_BE_VERSION="a9e1e1dd6072ffb15c0fcb8938d9ea0d8900c0da" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 24 Apr 2024 02:42:03 PM CEST" VOLUMIO_VERSION="3.661" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="c434411fe8754b648dc7feb1d8f43761"