-- Logs begin at Thu 2019-02-14 20:12:00 AEST, end at Fri 2024-04-12 07:23:04 AEST. --
Apr 12 07:22:53 volumio volumio[868]: info: CoreCommandRouter::volumioPlay
Apr 12 07:22:53 volumio volumio[868]: info: CoreStateMachine::play index undefined
Apr 12 07:22:53 volumio volumio[868]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 12 07:22:53 volumio volumio[868]: info: CorePlayQueue::getTrack 0
Apr 12 07:22:53 volumio volumio[868]: info: CoreStateMachine::startPlaybackTimer
Apr 12 07:22:53 volumio volumio[868]: info: CorePlayQueue::getTrack 0
Apr 12 07:22:53 volumio volumio[868]: info: [1712870573800] ControllerSpotify::clearAddPlayTrack
Apr 12 07:22:53 volumio volumio[868]: info: Sending Spotify command with payload to local API: /player/play
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=trace msg="fetched new page 0 with 1 items (list: 1)"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="loading track spotify:track:0h3Xy4V4apMraB5NuM8U7Z (paused: false, position: 0ms)"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=trace msg="emitting websocket event: will_play"
Apr 12 07:22:54 volumio volumio[868]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","play_origin":"go-librespot"}}
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:0h3Xy4V4apMraB5NuM8U7Z"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="requested aes key for file 316785cb685f8ff1b542152a87620426f2fed531, gid: 0h3Xy4V4apMraB5NuM8U7Z"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2893"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Apr 12 07:22:54 volumio volumio[868]: info: CoreCommandRouter::volumioNext
Apr 12 07:22:54 volumio volumio[868]: info: CoreStateMachine::next
Apr 12 07:22:54 volumio volumio[868]: info: CoreStateMachine::stop
Apr 12 07:22:54 volumio volumio[868]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 12 07:22:54 volumio volumio[868]: info: CoreStateMachine::play index undefined
Apr 12 07:22:54 volumio volumio[868]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 12 07:22:54 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:54 volumio volumio[868]: info: CoreStateMachine::startPlaybackTimer
Apr 12 07:22:54 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:54 volumio volumio[868]: info: [1712870574745] ControllerSpotify::clearAddPlayTrack
Apr 12 07:22:54 volumio volumio[868]: info: Sending Spotify command with payload to local API: /player/play
Apr 12 07:22:54 volumio volumio[868]: info: CoreStateMachine::updateTrackBlock
Apr 12 07:22:54 volumio volumio[868]: info: CorePlayQueue::getTrackBlock
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1999"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=debug msg="fetched first chunk of 16, total size is 8157712 bytes"
Apr 12 07:22:54 volumio go-librespot[1085]: time="2024-04-12T07:22:54+10:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)"
Apr 12 07:22:55 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=info msg="loaded track \"Stumblin' In\" (uri: spotify:track:0h3Xy4V4apMraB5NuM8U7Z, paused: false, position: 0ms, duration: 213363ms)"
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=debug msg="fetched chunk 3/15, size: 524288"
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=debug msg="fetched chunk 2/15, size: 524288"
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=debug msg="fetched chunk 1/15, size: 524288"
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=trace msg="emitting websocket event: metadata"
Apr 12 07:22:55 volumio volumio[868]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","name":"Stumblin' In","artist_names":["CYRIL"],"album_name":"Stumblin' In","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0257732f3a97f6d356b547cf1e","position":0,"duration":213363,"release_date":"year:2023 month:11 day:10","track_number":1,"disc_number":1}}
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=trace msg="emitting websocket event: playing"
Apr 12 07:22:55 volumio volumio[868]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","play_origin":"go-librespot"}}
Apr 12 07:22:55 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:22:55 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e0257732f3a97f6d356b547cf1e","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:55 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:22:55 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:55 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e0257732f3a97f6d356b547cf1e","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:55 volumio volumio[868]: verbose: CURRENT POSITION 11
Apr 12 07:22:55 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:22:55 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus stop
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=trace msg="fetched new page 0 with 1 items (list: 1)"
Apr 12 07:22:55 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:22:55 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e0257732f3a97f6d356b547cf1e","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:55 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:22:55 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:55 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stumblin' In","artist":"CYRIL","album":"Stumblin' In","albumart":"https://i.scdn.co/image/ab67616d00001e0257732f3a97f6d356b547cf1e","uri":"spotify:track:0h3Xy4V4apMraB5NuM8U7Z","trackType":"spotify","seek":0,"duration":213,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:55 volumio volumio[868]: verbose: CURRENT POSITION 11
Apr 12 07:22:55 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:22:55 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus play
Apr 12 07:22:55 volumio volumio[868]: info: Received an update from plugin. extracting info from payload
Apr 12 07:22:55 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:55 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:55 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:22:55 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:55 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:55 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:55 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:55 volumio go-librespot[1085]: time="2024-04-12T07:22:55+10:00" level=debug msg="loading track spotify:track:34Yl756FwYuZldE9xnshj5 (paused: false, position: 162ms)"
Apr 12 07:22:55 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:55 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:55 volumio volumio[868]: info: touch_display: Setting screensaver timeout to 0 seconds.
Apr 12 07:22:55 volumio volumio[868]: info: CoreCommandRouter::volumioGetState
Apr 12 07:22:55 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=trace msg="emitting websocket event: will_play"
Apr 12 07:22:56 volumio volumio[868]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0
Apr 12 07:22:56 volumio volumio[868]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:34Yl756FwYuZldE9xnshj5","play_origin":"go-librespot"}}
Apr 12 07:22:56 volumio volumio[868]: info: touch_display: Setting screensaver timeout to 0 seconds.
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:34Yl756FwYuZldE9xnshj5"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=debug msg="requested aes key for file 72a9115b8e19291ae76a065c8b81a2426ef700df, gid: 34Yl756FwYuZldE9xnshj5"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=debug msg="fetched first chunk of 10, total size is 5025404 bytes"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=trace msg="seek to 162ms (diff: 144ms, samples: 7144, bytes: 1328)"
Apr 12 07:22:56 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=info msg="loaded track \"if u think i'm pretty\" (uri: spotify:track:34Yl756FwYuZldE9xnshj5, paused: false, position: 162ms, duration: 128205ms)"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=debug msg="fetched chunk 1/9, size: 524288"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=debug msg="fetched chunk 3/9, size: 524288"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=debug msg="fetched chunk 2/9, size: 524288"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:56 volumio go-librespot[1085]: time="2024-04-12T07:22:56+10:00" level=trace msg="emitting websocket event: metadata"
Apr 12 07:22:56 volumio volumio[868]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:34Yl756FwYuZldE9xnshj5","name":"if u think i'm pretty","artist_names":["Artemas"],"album_name":"if u think i'm pretty","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a05f71a30fa52bf9c2b046b7","position":162,"duration":128205,"release_date":"year:2023 month:10 day:24","track_number":1,"disc_number":1}}
Apr 12 07:22:57 volumio go-librespot[1085]: time="2024-04-12T07:22:57+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:57 volumio go-librespot[1085]: time="2024-04-12T07:22:57+10:00" level=trace msg="emitting websocket event: playing"
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:34Yl756FwYuZldE9xnshj5","play_origin":"go-librespot"}}
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"if u think i'm pretty","artist":"Artemas","album":"if u think i'm pretty","albumart":"https://i.scdn.co/image/ab67616d00001e02a05f71a30fa52bf9c2b046b7","uri":"spotify:track:34Yl756FwYuZldE9xnshj5","trackType":"spotify","seek":162,"duration":128,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:57 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"if u think i'm pretty","artist":"Artemas","album":"if u think i'm pretty","albumart":"https://i.scdn.co/image/ab67616d00001e02a05f71a30fa52bf9c2b046b7","uri":"spotify:track:34Yl756FwYuZldE9xnshj5","trackType":"spotify","seek":162,"duration":128,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:57 volumio volumio[868]: verbose: CURRENT POSITION 11
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus play
Apr 12 07:22:57 volumio volumio[868]: info: Received an update from plugin. extracting info from payload
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"if u think i'm pretty","artist":"Artemas","album":"if u think i'm pretty","albumart":"https://i.scdn.co/image/ab67616d00001e02a05f71a30fa52bf9c2b046b7","uri":"spotify:track:34Yl756FwYuZldE9xnshj5","trackType":"spotify","seek":162,"duration":128,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:57 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"if u think i'm pretty","artist":"Artemas","album":"if u think i'm pretty","albumart":"https://i.scdn.co/image/ab67616d00001e02a05f71a30fa52bf9c2b046b7","uri":"spotify:track:34Yl756FwYuZldE9xnshj5","trackType":"spotify","seek":162,"duration":128,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:57 volumio volumio[868]: verbose: CURRENT POSITION 11
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus play
Apr 12 07:22:57 volumio volumio[868]: info: Received an update from plugin. extracting info from payload
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::volumioNext
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::next
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::stop
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::stPlaybackTimer
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::updateTrackBlock
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrackBlock
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::serviceStop
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:22:57 volumio volumio[868]: info: CoreCommandRouter::serviceStop
Apr 12 07:22:57 volumio volumio[868]: info: Spotify Stop
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: SPOTIFY STOP
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: {"status":"play","position":11,"title":"if u think i'm pretty","artist":"Artemas","album":"if u think i'm pretty","albumart":"https://i.scdn.co/image/ab67616d0000b273a05f71a30fa52bf9c2b046b7","uri":"spotify:track:34Yl756FwYuZldE9xnshj5","trackType":"spotify","codec":"ogg","seek":162,"duration":128,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"}
Apr 12 07:22:57 volumio volumio[868]: info: Sending Spotify command to local API: /player/pause
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::play index undefined
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::startPlaybackTimer
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:22:57 volumio volumio[868]: info: [1712870577591] ControllerSpotify::clearAddPlayTrack
Apr 12 07:22:57 volumio volumio[868]: info: Sending Spotify command with payload to local API: /player/play
Apr 12 07:22:57 volumio volumio[868]: info: CoreStateMachine::updateTrackBlock
Apr 12 07:22:57 volumio volumio[868]: info: CorePlayQueue::getTrackBlock
Apr 12 07:22:57 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:57 volumio volumio[868]: info: touch_display: Setting screensaver timeout to 120 seconds.
Apr 12 07:22:57 volumio go-librespot[1085]: time="2024-04-12T07:22:57+10:00" level=debug msg="pause track at 1317ms"
Apr 12 07:22:57 volumio go-librespot[1085]: time="2024-04-12T07:22:57+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=trace msg="fetched new page 0 with 1 items (list: 1)"
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=debug msg="loading track spotify:track:0ZL3KCVOotXnC5trEE3XPa (paused: false, position: 1ms)"
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=trace msg="emitting websocket event: will_play"
Apr 12 07:22:58 volumio volumio[868]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","play_origin":"go-librespot"}}
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:0ZL3KCVOotXnC5trEE3XPa"
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=debug msg="requested aes key for file 92f24217e930e5132699bad9207cdaaff4a0d407, gid: 0ZL3KCVOotXnC5trEE3XPa"
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=debug msg="fetched first chunk of 18, total size is 9357872 bytes"
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)"
Apr 12 07:22:58 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Apr 12 07:22:58 volumio go-librespot[1085]: time="2024-04-12T07:22:58+10:00" level=info msg="loaded track \"The Worst Person Alive\" (uri: spotify:track:0ZL3KCVOotXnC5trEE3XPa, paused: false, position: 1ms, duration: 210417ms)"
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=debug msg="fetched chunk 3/17, size: 524288"
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=debug msg="fetched chunk 2/17, size: 524288"
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=trace msg="emitting websocket event: metadata"
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","name":"The Worst Person Alive","artist_names":["G Flip"],"album_name":"The Worst Person Alive","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","position":1,"duration":210417,"release_date":"year:2023 month:6 day:28","track_number":1,"disc_number":1}}
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=debug msg="fetched chunk 1/17, size: 524288"
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=trace msg="emitting websocket event: paused"
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","play_origin":"go-librespot"}}
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: {"status":"pause","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":1,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:59 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:22:59 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:22:59 volumio volumio[868]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":1,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:59 volumio volumio[868]: verbose: CURRENT POSITION 41
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::syncState stateService pause
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus stop
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:59 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:22:59 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:22:59 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:22:59 volumio go-librespot[1085]: time="2024-04-12T07:22:59+10:00" level=trace msg="emitting websocket event: playing"
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","play_origin":"go-librespot"}}
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":1,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:59 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:22:59 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:22:59 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":1,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:59 volumio volumio[868]: verbose: CURRENT POSITION 41
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus stop
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":1,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:59 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:22:59 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:22:59 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":1,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:22:59 volumio volumio[868]: verbose: CURRENT POSITION 41
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus play
Apr 12 07:22:59 volumio volumio[868]: info: Received an update from plugin. extracting info from payload
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:59 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:22:59 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:22:59 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:59 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:22:59 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:22:59 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:59 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:22:59 volumio volumio[868]: info: touch_display: Setting screensaver timeout to 0 seconds.
Apr 12 07:23:00 volumio volumio[868]: info: CoreCommandRouter::volumioPrevious
Apr 12 07:23:00 volumio volumio[868]: info: CoreStateMachine::previous
Apr 12 07:23:00 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:00 volumio volumio[868]: info: Spotify seek to: 0
Apr 12 07:23:00 volumio volumio[868]: info: Sending Spotify command with payload to local API: /player/seek
Apr 12 07:23:00 volumio go-librespot[1085]: time="2024-04-12T07:23:00+10:00" level=debug msg="seek track to 0ms"
Apr 12 07:23:00 volumio go-librespot[1085]: time="2024-04-12T07:23:00+10:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)"
Apr 12 07:23:00 volumio go-librespot[1085]: time="2024-04-12T07:23:00+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:23:00 volumio go-librespot[1085]: time="2024-04-12T07:23:00+10:00" level=trace msg="emitting websocket event: seek"
Apr 12 07:23:00 volumio volumio[868]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","position":0,"duration":210417,"play_origin":"go-librespot"}}
Apr 12 07:23:00 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:23:00 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:23:00 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:23:00 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:00 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:23:00 volumio volumio[868]: verbose: CURRENT POSITION 41
Apr 12 07:23:00 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:23:00 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus play
Apr 12 07:23:00 volumio volumio[868]: info: Received an update from plugin. extracting info from payload
Apr 12 07:23:00 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:23:00 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:00 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:23:00 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:23:00 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:23:00 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:00 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:23:00 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:23:00 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:23:01 volumio volumio[868]: info: CoreCommandRouter::volumioPrevious
Apr 12 07:23:01 volumio volumio[868]: info: CoreStateMachine::previous
Apr 12 07:23:01 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:01 volumio volumio[868]: info: CoreStateMachine::stop
Apr 12 07:23:01 volumio volumio[868]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 12 07:23:01 volumio volumio[868]: info: CoreStateMachine::stPlaybackTimer
Apr 12 07:23:01 volumio volumio[868]: info: CoreStateMachine::updateTrackBlock
Apr 12 07:23:01 volumio volumio[868]: info: CorePlayQueue::getTrackBlock
Apr 12 07:23:01 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:23:01 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:01 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:23:01 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:23:01 volumio volumio[868]: info: CoreStateMachine::serviceStop
Apr 12 07:23:01 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:01 volumio volumio[868]: info: CoreCommandRouter::serviceStop
Apr 12 07:23:01 volumio volumio[868]: info: Spotify Stop
Apr 12 07:23:01 volumio volumio[868]: SPOTIFY: SPOTIFY STOP
Apr 12 07:23:01 volumio volumio[868]: SPOTIFY: {"status":"play","position":41,"title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d0000b273748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","codec":"ogg","seek":0,"duration":210,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"}
Apr 12 07:23:01 volumio volumio[868]: info: Sending Spotify command to local API: /player/pause
Apr 12 07:23:01 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:23:01 volumio volumio[868]: info: touch_display: Setting screensaver timeout to 120 seconds.
Apr 12 07:23:01 volumio go-librespot[1085]: time="2024-04-12T07:23:01+10:00" level=debug msg="pause track at 1266ms"
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::play index undefined
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 12 07:23:02 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::startPlaybackTimer
Apr 12 07:23:02 volumio volumio[868]: info: CorePlayQueue::getTrack 41
Apr 12 07:23:02 volumio volumio[868]: info: [1712870582073] ControllerSpotify::clearAddPlayTrack
Apr 12 07:23:02 volumio volumio[868]: info: Sending Spotify command with payload to local API: /player/play
Apr 12 07:23:02 volumio volumio[868]: info: CoreCommandRouter::volumioPrevious
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::previous
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::updateTrackBlock
Apr 12 07:23:02 volumio volumio[868]: info: CorePlayQueue::getTrackBlock
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::serviceClearAddPlay
Apr 12 07:23:02 volumio volumio[868]: info: CoreCommandRouter::serviceClearAddPlayTracks
Apr 12 07:23:02 volumio volumio[868]: error: WARNING: No clearAddPlayTracks method for service spop
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=trace msg="emitting websocket event: paused"
Apr 12 07:23:02 volumio volumio[868]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","play_origin":"go-librespot"}}
Apr 12 07:23:02 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:23:02 volumio volumio[868]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:23:02 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:23:02 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:23:02 volumio volumio[868]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:23:02 volumio volumio[868]: verbose: CURRENT POSITION 11
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::syncState stateService pause
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus stop
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:23:02 volumio volumio[868]: info: CorePlayQueue::getTrack 11
Apr 12 07:23:02 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:23:02 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:23:02 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=trace msg="fetched new page 0 with 1 items (list: 1)"
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=debug msg="loading track spotify:track:0ZL3KCVOotXnC5trEE3XPa (paused: false, position: 0ms)"
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=trace msg="emitting websocket event: will_play"
Apr 12 07:23:02 volumio volumio[868]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","play_origin":"go-librespot"}}
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:0ZL3KCVOotXnC5trEE3XPa"
Apr 12 07:23:02 volumio go-librespot[1085]: time="2024-04-12T07:23:02+10:00" level=debug msg="requested aes key for file 92f24217e930e5132699bad9207cdaaff4a0d407, gid: 0ZL3KCVOotXnC5trEE3XPa"
Apr 12 07:23:02 volumio volumio[868]: info: CoreCommandRouter::volumioPrevious
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::previous
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::updateTrackBlock
Apr 12 07:23:02 volumio volumio[868]: info: CorePlayQueue::getTrackBlock
Apr 12 07:23:02 volumio volumio[868]: info: CoreStateMachine::serviceClearAddPlay
Apr 12 07:23:02 volumio volumio[868]: info: CoreCommandRouter::serviceClearAddPlayTracks
Apr 12 07:23:02 volumio volumio[868]: error: WARNING: No clearAddPlayTracks method for service spop
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=debug msg="fetched first chunk of 18, total size is 9357872 bytes"
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)"
Apr 12 07:23:03 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=info msg="loaded track \"The Worst Person Alive\" (uri: spotify:track:0ZL3KCVOotXnC5trEE3XPa, paused: false, position: 0ms, duration: 210417ms)"
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=debug msg="fetched chunk 2/17, size: 524288"
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=debug msg="fetched chunk 3/17, size: 524288"
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=debug msg="fetched chunk 1/17, size: 524288"
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=trace msg="emitting websocket event: metadata"
Apr 12 07:23:03 volumio volumio[868]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","name":"The Worst Person Alive","artist_names":["G Flip"],"album_name":"The Worst Person Alive","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","position":0,"duration":210417,"release_date":"year:2023 month:6 day:28","track_number":1,"disc_number":1}}
Apr 12 07:23:03 volumio volumio[868]: info: CoreCommandRouter::volumioPrevious
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::previous
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::updateTrackBlock
Apr 12 07:23:03 volumio volumio[868]: info: CorePlayQueue::getTrackBlock
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::serviceClearAddPlay
Apr 12 07:23:03 volumio volumio[868]: info: CoreCommandRouter::serviceClearAddPlayTracks
Apr 12 07:23:03 volumio volumio[868]: error: WARNING: No clearAddPlayTracks method for service spop
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 12 07:23:03 volumio go-librespot[1085]: time="2024-04-12T07:23:03+10:00" level=trace msg="emitting websocket event: playing"
Apr 12 07:23:03 volumio volumio[868]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","play_origin":"go-librespot"}}
Apr 12 07:23:03 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:23:03 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:23:03 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:23:03 volumio volumio[868]: info: CorePlayQueue::getTrack 50
Apr 12 07:23:03 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:23:03 volumio volumio[868]: verbose: CURRENT POSITION 50
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus stop
Apr 12 07:23:03 volumio volumio[868]: SPOTIFY: PUSH STATE SPOTIFY
Apr 12 07:23:03 volumio volumio[868]: SPOTIFY: {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:23:03 volumio volumio[868]: info: CoreCommandRouter::servicePushState
Apr 12 07:23:03 volumio volumio[868]: info: CorePlayQueue::getTrack 50
Apr 12 07:23:03 volumio volumio[868]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Worst Person Alive","artist":"G Flip","album":"The Worst Person Alive","albumart":"https://i.scdn.co/image/ab67616d00001e02748fca61f250ad58cdec27d0","uri":"spotify:track:0ZL3KCVOotXnC5trEE3XPa","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 12 07:23:03 volumio volumio[868]: verbose: CURRENT POSITION 50
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::syncState stateService play
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::syncState currentStatus play
Apr 12 07:23:03 volumio volumio[868]: info: Received an update from plugin. extracting info from payload
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:23:03 volumio volumio[868]: info: CorePlayQueue::getTrack 50
Apr 12 07:23:03 volumio volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 12 07:23:03 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:23:03 volumio volumio[868]: info: CoreStateMachine::pushState
Apr 12 07:23:03 volumio volumio[868]: info: CorePlayQueue::getTrack 50
Apr 12 07:23:04 volumio volumio[868]: info: CoreCommandRouter::volumioPushState
Apr 12 07:23:04 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:23:04 volumio volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
Apr 12 07:23:04 volumio volumio[868]: info: CoreCommandRouter::volumioPrevious
Apr 12 07:23:04 volumio volumio[868]: info: CoreStateMachine::previous
Apr 12 07:23:04 volumio volumio[868]: info: CorePlayQueue::getTrack 50
Apr 12 07:23:04 volumio volumio[868]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Apr 12 07:23:04 volumio volumio[868]: TypeError: Cannot read property 'service' of undefined
Apr 12 07:23:04 volumio volumio[868]: at CoreStateMachine.previous (/volumio/app/statemachine.js:1315:97)
Apr 12 07:23:04 volumio volumio[868]: at CoreCommandRouter.volumioPrevious (/volumio/app/index.js:95:28)
Apr 12 07:23:04 volumio volumio[868]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:246:33)
Apr 12 07:23:04 volumio volumio[868]: at Socket.emit (events.js:315:20)
Apr 12 07:23:04 volumio volumio[868]: at /volumio/node_modules/socket.io/lib/socket.js:503:12
Apr 12 07:23:04 volumio volumio[868]: at processTicksAndRejections (internal/process/task_queues.js:75:11)
Apr 12 07:23:04 volumio volumio[868]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Apr 12 07:23:04 volumio sudo[1897]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-12 07:22
Apr 12 07:23:04 volumio sudo[1897]: pam_unix(sudo:session): session opened for user root by (uid=0)
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
VOLUMIO_BUILD_VERSION="56d8f4e08ca3cb143324aa0740c362c469043a9b"
VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71"
VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1"
VOLUMIO_BE_VERSION="a77c7968e70cebb21b39a3791120006fed600769"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Sun 31 Mar 2024 12:34:13 PM CEST"
VOLUMIO_VERSION="3.637"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="41a89107ca82d89cff75a3106ff77fdf"