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