-- 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"