-- Logs begin at Sat 2025-03-15 10:23:21 CET, end at Sat 2025-03-15 19:46:13 CET. -- Mar 15 19:45:01 volumio volumio[1091]: verbose: New Socket.io Connection to 192.168.178.10 from 192.168.178.20 UA: Mozilla/5.0 (Linux; Android 14; SM-G990B2 Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.137 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Mar 15 19:45:01 volumio volumio[1091]: info: CoreCommandRouter::volumioGetState Mar 15 19:45:01 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 15 19:45:01 volumio volumio[1091]: info: Listing playlists Mar 15 19:45:01 volumio volumio[1091]: info: CoreCommandRouter::volumioGetQueue Mar 15 19:45:01 volumio volumio[1091]: info: CoreStateMachine::getQueue Mar 15 19:45:01 volumio volumio[1091]: info: CorePlayQueue::getQueue Mar 15 19:45:02 volumio go-librespot[1545]: time="2025-03-15T19:45:02+01:00" level=trace msg="sent dealer ping" Mar 15 19:45:02 volumio go-librespot[1545]: time="2025-03-15T19:45:02+01:00" level=trace msg="received dealer pong" Mar 15 19:45:02 volumio volumio[1091]: info: VolumeController::SetAlsaVolume+ Mar 15 19:45:02 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:02 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:02 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:02 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 96 Mar 15 19:45:02 volumio volumio[1091]: SPOTIFY: SPOTIFY VOLUME 95 Mar 15 19:45:02 volumio volumio[1091]: SPOTIFY: VOLUMIO VOLUME 96 Mar 15 19:45:02 volumio volumio[1091]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 15 19:45:03 volumio volumio[1091]: info: VolumeController::SetAlsaVolume+ Mar 15 19:45:03 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:03 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:03 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:03 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:03 volumio volumio[1091]: SPOTIFY: SPOTIFY VOLUME 95 Mar 15 19:45:03 volumio volumio[1091]: SPOTIFY: VOLUMIO VOLUME 97 Mar 15 19:45:03 volumio volumio[1091]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 15 19:45:03 volumio volumio[1091]: info: Setting Spotify Volume from Volumio: 97 Mar 15 19:45:04 volumio volumio[1091]: SPOTIFY: SETTING SPOTIFY VOLUME 97 Mar 15 19:45:04 volumio volumio[1091]: info: Sending Spotify command with payload to local API: /player/volume Mar 15 19:45:04 volumio go-librespot[1545]: time="2025-03-15T19:45:04+01:00" level=debug msg="update volume to 63568/65535" Mar 15 19:45:05 volumio go-librespot[1545]: time="2025-03-15T19:45:05+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 15 19:45:05 volumio go-librespot[1545]: time="2025-03-15T19:45:05+01:00" level=trace msg="emitting websocket event: volume" Mar 15 19:45:05 volumio volumio[1091]: SPOTIFY: received: {"type":"volume","data":{"value":97,"max":100}} Mar 15 19:45:05 volumio volumio[1091]: SPOTIFY: RECEIVED SPOTIFY VOLUME 97 Mar 15 19:45:08 volumio go-librespot[1545]: time="2025-03-15T19:45:08+01:00" level=debug msg="fetched chunk 32/33, size: 524288" uri="spotify:track:6k1NHPGSRL7Dk3YzSLrYh7" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="resolved context of track" uri="spotify:album:3qxjWgpoCaLjq2Er1qszvR" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=trace msg="fetched new page 0 with 4 items (list: 4)" uri="spotify:album:3qxjWgpoCaLjq2Er1qszvR" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","play_origin":"playlist"}} Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="selected format OGG_VORBIS_320 (2d95f962e993ea43414a1ba9e39f90e982b38110)" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="requested aes key for file 2d95f962e993ea43414a1ba9e39f90e982b38110, gid: 1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="fetched first chunk of 20, total size is 10055960 bytes" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=info msg="loaded track \"Raymond\" (paused: false, position: 0ms, duration: 268895ms, prefetched: false)" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=trace msg="scheduling prefetch in 239s" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","name":"Raymond","artist_names":["Hi \u0026 Saberhägen"],"album_name":"LIONOIL002","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","position":0,"duration":268895,"release_date":"year:2016 month:1 day:11","track_number":2,"disc_number":1}} Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:10 volumio go-librespot[1545]: time="2025-03-15T19:45:10+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","play_origin":"playlist"}} Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Raymond","artist":"Hi & Saberhägen","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","trackType":"spotify","seek":0,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:10 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:10 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:10 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:10 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:10 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (Raymond) and artist (Hi & Saberhägen) passed on explicitly Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Raymond","artist":"Hi & Saberhägen","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","trackType":"spotify","seek":0,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:10 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:10 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:10 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:10 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:11 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Raymond","url":"https://www.last.fm/music/Hi+&+Saberh%C3%A4gen/_/Raymond","duration":"269000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"35","playcount":"104","artist":{"name":"Hi & Saberhägen","url":"https://www.last.fm/music/Hi+&+Saberh%C3%A4gen"},"album":{"artist":"Various Artists","title":"Lionoil002 - Ep","url":"https://www.last.fm/music/Various+Artists/Lionoil002+-+Ep","image":[{"@":{"size":"small"}},{"@":{"size":"medium"}},{"@":{"size":"large"}},{"@":{"size":"extralarge"}}]},"userplaycount":"1","userloved":"0","toptags":""}} Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=debug msg="seek track to 51998ms" Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=trace msg="seek to 51998ms (diff: 102ms, samples: 2293111, bytes: 1983320)" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=debug msg="fetched chunk 6/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=trace msg="scheduling prefetch in 187s" Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:13 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","position":51998,"duration":268895,"play_origin":"playlist"}} Mar 15 19:45:13 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:13 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Raymond","artist":"Hi & Saberhägen","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","trackType":"spotify","seek":51998,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:13 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:13 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:13 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:13 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:13 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:13 volumio go-librespot[1545]: time="2025-03-15T19:45:13+01:00" level=debug msg="fetched chunk 5/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=debug msg="seek track to 108879ms" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=debug msg="fetched chunk 9/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=debug msg="fetched chunk 8/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=trace msg="seek to 108879ms (diff: 37ms, samples: 4801563, bytes: 4271841)" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=debug msg="fetched chunk 11/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=debug msg="fetched chunk 10/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=trace msg="scheduling prefetch in 130s" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:15 volumio go-librespot[1545]: time="2025-03-15T19:45:15+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:15 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","position":108879,"duration":268895,"play_origin":"playlist"}} Mar 15 19:45:15 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:15 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Raymond","artist":"Hi & Saberhägen","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","trackType":"spotify","seek":108879,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:15 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:15 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:15 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:15 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:15 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=debug msg="seek track to 151684ms" Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=trace msg="seek to 151684ms (diff: 167ms, samples: 6689264, bytes: 5863100)" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=debug msg="fetched chunk 14/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=debug msg="fetched chunk 12/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=trace msg="scheduling prefetch in 87s" Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:18 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","position":151684,"duration":268895,"play_origin":"playlist"}} Mar 15 19:45:18 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:18 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Raymond","artist":"Hi & Saberhägen","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","trackType":"spotify","seek":151684,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:18 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:18 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:18 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:18 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:18 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:18 volumio go-librespot[1545]: time="2025-03-15T19:45:18+01:00" level=debug msg="fetched chunk 13/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=debug msg="seek track to 207130ms" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=debug msg="fetched chunk 16/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=debug msg="fetched chunk 15/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=trace msg="seek to 207130ms (diff: 29ms, samples: 9134433, bytes: 7882843)" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=debug msg="fetched chunk 17/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=debug msg="fetched chunk 18/19, size: 524288" uri="spotify:track:1G316DGRV4MOY1QgNJtSlv" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=trace msg="scheduling prefetch in 32s" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:22 volumio go-librespot[1545]: time="2025-03-15T19:45:22+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:22 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","position":207130,"duration":268895,"play_origin":"playlist"}} Mar 15 19:45:22 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:22 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Raymond","artist":"Hi & Saberhägen","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:1G316DGRV4MOY1QgNJtSlv","trackType":"spotify","seek":207130,"duration":268,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:22 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:22 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:22 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:22 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:22 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="resolved context of track" uri="spotify:album:3qxjWgpoCaLjq2Er1qszvR" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=trace msg="fetched new page 0 with 4 items (list: 4)" uri="spotify:album:3qxjWgpoCaLjq2Er1qszvR" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","play_origin":"playlist"}} Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="selected format OGG_VORBIS_320 (26c96364d888ba8de828d5088386950fa8b2b5a1)" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="requested aes key for file 26c96364d888ba8de828d5088386950fa8b2b5a1, gid: 2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="fetched first chunk of 30, total size is 15586584 bytes" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=info msg="loaded track \"Chat Room\" (paused: false, position: 0ms, duration: 375174ms, prefetched: false)" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="fetched chunk 1/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="fetched chunk 2/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=trace msg="scheduling prefetch in 345s" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","name":"Chat Room","artist_names":["Percy Main"],"album_name":"LIONOIL002","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","position":0,"duration":375174,"release_date":"year:2016 month:1 day:11","track_number":4,"disc_number":1}} Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="fetched chunk 3/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:25 volumio go-librespot[1545]: time="2025-03-15T19:45:25+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","play_origin":"playlist"}} Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Chat Room","artist":"Percy Main","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","trackType":"spotify","seek":0,"duration":375,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:25 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:25 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:25 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:25 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:25 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (Chat Room) and artist (Percy Main) passed on explicitly Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:25 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Chat Room","url":"https://www.last.fm/music/Percy+Main/_/Chat+Room","duration":"375000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"19","playcount":"36","artist":{"name":"Percy Main","url":"https://www.last.fm/music/Percy+Main"},"album":{"artist":"Various Artists","title":"LIONOIL002","url":"https://www.last.fm/music/Various+Artists/LIONOIL002","image":[{"@":{"size":"small"}},{"@":{"size":"medium"}},{"@":{"size":"large"}},{"@":{"size":"extralarge"}}]},"userplaycount":"0","userloved":"0","toptags":""}} Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Chat Room","artist":"Percy Main","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","trackType":"spotify","seek":0,"duration":375,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:25 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:25 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:25 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:25 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:27 volumio go-librespot[1545]: time="2025-03-15T19:45:27+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:27 volumio go-librespot[1545]: time="2025-03-15T19:45:27+01:00" level=debug msg="seek track to 81368ms" Mar 15 19:45:27 volumio go-librespot[1545]: time="2025-03-15T19:45:27+01:00" level=debug msg="fetched chunk 9/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:27 volumio go-librespot[1545]: time="2025-03-15T19:45:27+01:00" level=debug msg="fetched chunk 7/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:27 volumio go-librespot[1545]: time="2025-03-15T19:45:27+01:00" level=debug msg="fetched chunk 6/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:27 volumio go-librespot[1545]: time="2025-03-15T19:45:27+01:00" level=trace msg="seek to 81368ms (diff: 128ms, samples: 3588328, bytes: 3147668)" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:27 volumio go-librespot[1545]: time="2025-03-15T19:45:27+01:00" level=debug msg="fetched chunk 8/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:28 volumio go-librespot[1545]: time="2025-03-15T19:45:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:28 volumio go-librespot[1545]: time="2025-03-15T19:45:28+01:00" level=trace msg="scheduling prefetch in 263s" Mar 15 19:45:28 volumio go-librespot[1545]: time="2025-03-15T19:45:28+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:28 volumio go-librespot[1545]: time="2025-03-15T19:45:28+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:28 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","position":81368,"duration":375174,"play_origin":"playlist"}} Mar 15 19:45:28 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:28 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Chat Room","artist":"Percy Main","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","trackType":"spotify","seek":81368,"duration":375,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:28 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:28 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:28 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:28 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:28 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=debug msg="seek track to 202818ms" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=debug msg="fetched chunk 16/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=debug msg="fetched chunk 15/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=trace msg="seek to 202818ms (diff: 92ms, samples: 8944273, bytes: 8355226)" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=debug msg="fetched chunk 17/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=debug msg="fetched chunk 18/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=trace msg="scheduling prefetch in 142s" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:29 volumio go-librespot[1545]: time="2025-03-15T19:45:29+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:29 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","position":202818,"duration":375174,"play_origin":"playlist"}} Mar 15 19:45:29 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:29 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Chat Room","artist":"Percy Main","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:2zaGBE2ePRNOyihiYG7o0c","trackType":"spotify","seek":202818,"duration":375,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:29 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:29 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:29 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:29 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:29 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:30 volumio go-librespot[1545]: time="2025-03-15T19:45:30+01:00" level=debug msg="fetched chunk 19/29, size: 524288" uri="spotify:track:2zaGBE2ePRNOyihiYG7o0c" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=debug msg="resolved context of track" uri="spotify:album:3qxjWgpoCaLjq2Er1qszvR" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=trace msg="fetched new page 0 with 4 items (list: 4)" uri="spotify:album:3qxjWgpoCaLjq2Er1qszvR" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:45:31 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","play_origin":"playlist"}} Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=debug msg="selected format OGG_VORBIS_320 (93b0cd29471e5a010c3eac89afccfda85e0df2ce)" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=debug msg="requested aes key for file 93b0cd29471e5a010c3eac89afccfda85e0df2ce, gid: 32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=debug msg="fetched first chunk of 26, total size is 13182316 bytes" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 19:45:31 volumio go-librespot[1545]: time="2025-03-15T19:45:31+01:00" level=info msg="loaded track \"In Twos\" (paused: false, position: 0ms, duration: 345793ms, prefetched: false)" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=debug msg="fetched chunk 3/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=debug msg="fetched chunk 1/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=trace msg="scheduling prefetch in 316s" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:32 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","name":"In Twos","artist_names":["Telfort"],"album_name":"LIONOIL002","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","position":0,"duration":345793,"release_date":"year:2016 month:1 day:11","track_number":3,"disc_number":1}} Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=debug msg="fetched chunk 2/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=trace msg="sent dealer ping" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:45:32 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","play_origin":"playlist"}} Mar 15 19:45:32 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:32 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"In Twos","artist":"Telfort","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","trackType":"spotify","seek":0,"duration":345,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:32 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:32 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:32 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:32 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:32 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (In Twos) and artist (Telfort) passed on explicitly Mar 15 19:45:32 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:32 volumio go-librespot[1545]: time="2025-03-15T19:45:32+01:00" level=trace msg="received dealer pong" Mar 15 19:45:32 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:32 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"In Twos","artist":"Telfort","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","trackType":"spotify","seek":1000,"duration":345,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:32 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:32 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:32 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:32 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:32 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=debug msg="seek track to 97162ms" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=debug msg="fetched chunk 8/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=debug msg="fetched chunk 7/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=trace msg="seek to 97162ms (diff: 90ms, samples: 4284844, bytes: 3697338)" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=debug msg="fetched chunk 9/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=debug msg="fetched chunk 10/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=trace msg="scheduling prefetch in 219s" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:33 volumio go-librespot[1545]: time="2025-03-15T19:45:33+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:33 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","position":97162,"duration":345793,"play_origin":"playlist"}} Mar 15 19:45:33 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:33 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"In Twos","artist":"Telfort","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","trackType":"spotify","seek":97162,"duration":345,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:33 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:33 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:33 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:33 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:33 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:36 volumio go-librespot[1545]: time="2025-03-15T19:45:36+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:36 volumio go-librespot[1545]: time="2025-03-15T19:45:36+01:00" level=debug msg="seek track to 189521ms" Mar 15 19:45:36 volumio go-librespot[1545]: time="2025-03-15T19:45:36+01:00" level=debug msg="fetched chunk 14/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:36 volumio go-librespot[1545]: time="2025-03-15T19:45:36+01:00" level=debug msg="fetched chunk 13/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:36 volumio go-librespot[1545]: time="2025-03-15T19:45:36+01:00" level=trace msg="seek to 189521ms (diff: 58ms, samples: 8357876, bytes: 7254799)" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:36 volumio go-librespot[1545]: time="2025-03-15T19:45:36+01:00" level=debug msg="fetched chunk 15/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:36 volumio go-librespot[1545]: time="2025-03-15T19:45:36+01:00" level=debug msg="fetched chunk 16/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:37 volumio go-librespot[1545]: time="2025-03-15T19:45:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:37 volumio go-librespot[1545]: time="2025-03-15T19:45:37+01:00" level=trace msg="scheduling prefetch in 126s" Mar 15 19:45:37 volumio go-librespot[1545]: time="2025-03-15T19:45:37+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:37 volumio go-librespot[1545]: time="2025-03-15T19:45:37+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:37 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","position":189521,"duration":345793,"play_origin":"playlist"}} Mar 15 19:45:37 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:37 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"In Twos","artist":"Telfort","album":"LIONOIL002","albumart":"https://i.scdn.co/image/ab67616d00001e0259f18fc62bc8ac46b9fe1be0","uri":"spotify:track:32oFfmDU8sxm9EwB6B7aXA","trackType":"spotify","seek":189521,"duration":345,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:37 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:37 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:37 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:37 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:37 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:38 volumio go-librespot[1545]: time="2025-03-15T19:45:38+01:00" level=debug msg="fetched chunk 17/25, size: 524288" uri="spotify:track:32oFfmDU8sxm9EwB6B7aXA" Mar 15 19:45:39 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"In Twos","url":"https://www.last.fm/music/Telfort/_/In+Twos","duration":"346000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"18","playcount":"26","artist":{"name":"Telfort","url":"https://www.last.fm/music/Telfort"},"album":{"artist":"Various Artists","title":"LIONOIL002","url":"https://www.last.fm/music/Various+Artists/LIONOIL002","image":[{"@":{"size":"small"}},{"@":{"size":"medium"}},{"@":{"size":"large"}},{"@":{"size":"extralarge"}}]},"userplaycount":"0","userloved":"0","toptags":""}} Mar 15 19:45:43 volumio go-librespot[1545]: time="2025-03-15T19:45:43+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:43 volumio go-librespot[1545]: time="2025-03-15T19:45:43+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:45:43 volumio go-librespot[1545]: time="2025-03-15T19:45:43+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:45:43 volumio go-librespot[1545]: time="2025-03-15T19:45:43+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:45:44 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1ZPumVevpVv55X7z3SuQn8","play_origin":"playlist"}} Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="selected format OGG_VORBIS_320 (c82f4b06f64254b4213483737cea3ed9ab7b0ea2)" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="requested aes key for file c82f4b06f64254b4213483737cea3ed9ab7b0ea2, gid: 1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="fetched first chunk of 28, total size is 14233812 bytes" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=info msg="loaded track \"Luna ácida - Balam Club Mix\" (paused: false, position: 1ms, duration: 305000ms, prefetched: false)" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="fetched chunk 1/27, size: 524288" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="fetched chunk 3/27, size: 524288" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="fetched chunk 2/27, size: 524288" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=trace msg="scheduling prefetch in 275s" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:44 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1ZPumVevpVv55X7z3SuQn8","name":"Luna ácida - Balam Club Mix","artist_names":["Populous","Balam","Fuera"],"album_name":"Luna ácida (Balam Club Mix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f37b546100b8faff3ba3a5e8","position":1,"duration":305000,"release_date":"year:2025 month:2 day:14","track_number":1,"disc_number":1}} Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:44 volumio go-librespot[1545]: time="2025-03-15T19:45:44+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:45:44 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1ZPumVevpVv55X7z3SuQn8","play_origin":"playlist"}} Mar 15 19:45:44 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:44 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Luna ácida - Balam Club Mix","artist":"Populous, Balam, Fuera","album":"Luna ácida (Balam Club Mix)","albumart":"https://i.scdn.co/image/ab67616d00001e02f37b546100b8faff3ba3a5e8","uri":"spotify:track:1ZPumVevpVv55X7z3SuQn8","trackType":"spotify","seek":1,"duration":305,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:44 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:44 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:44 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:44 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:44 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (Luna ácida - Balam Club Mix) and artist (Populous, Balam, Fuera) passed on explicitly Mar 15 19:45:44 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:45 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:45 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Luna ácida - Balam Club Mix","artist":"Populous, Balam, Fuera","album":"Luna ácida (Balam Club Mix)","albumart":"https://i.scdn.co/image/ab67616d00001e02f37b546100b8faff3ba3a5e8","uri":"spotify:track:1ZPumVevpVv55X7z3SuQn8","trackType":"spotify","seek":1,"duration":305,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:45 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:45 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:45 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:45 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:45 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Luna ácida - Balam Club Mix","url":"https://www.last.fm/music/Populous,+Balam,+Fuera/_/Luna+%C3%A1cida+-+Balam+Club+Mix","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"1","playcount":"1","artist":{"name":"Populous, Balam, Fuera","url":"https://www.last.fm/music/Populous,+Balam,+Fuera"},"userplaycount":"0","userloved":"0","toptags":""}} Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=debug msg="seek track to 109813ms" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=debug msg="fetched chunk 11/27, size: 524288" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=debug msg="fetched chunk 9/27, size: 524288" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=trace msg="seek to 109813ms (diff: 134ms, samples: 4842753, bytes: 5156308)" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=debug msg="fetched chunk 10/27, size: 524288" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=debug msg="fetched chunk 12/27, size: 524288" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=trace msg="scheduling prefetch in 165s" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:48 volumio go-librespot[1545]: time="2025-03-15T19:45:48+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:48 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:1ZPumVevpVv55X7z3SuQn8","position":109813,"duration":305000,"play_origin":"playlist"}} Mar 15 19:45:48 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:48 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Luna ácida - Balam Club Mix","artist":"Populous, Balam, Fuera","album":"Luna ácida (Balam Club Mix)","albumart":"https://i.scdn.co/image/ab67616d00001e02f37b546100b8faff3ba3a5e8","uri":"spotify:track:1ZPumVevpVv55X7z3SuQn8","trackType":"spotify","seek":109813,"duration":305,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:48 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:48 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:48 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:48 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:48 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:50 volumio go-librespot[1545]: time="2025-03-15T19:45:50+01:00" level=debug msg="fetched chunk 13/27, size: 524288" uri="spotify:track:1ZPumVevpVv55X7z3SuQn8" Mar 15 19:45:52 volumio go-librespot[1545]: time="2025-03-15T19:45:52+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:52 volumio go-librespot[1545]: time="2025-03-15T19:45:52+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:45:52 volumio go-librespot[1545]: time="2025-03-15T19:45:52+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:45:52 volumio go-librespot[1545]: time="2025-03-15T19:45:52+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:52 volumio go-librespot[1545]: time="2025-03-15T19:45:52+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:52 volumio go-librespot[1545]: time="2025-03-15T19:45:52+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:45:52 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4NAzeOi10pTqHlNvWxoWjA","play_origin":"playlist"}} Mar 15 19:45:52 volumio go-librespot[1545]: time="2025-03-15T19:45:52+01:00" level=debug msg="selected format OGG_VORBIS_320 (faa5144006c0b86c4d86e23368bd2f7c1426ccf5)" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:52 volumio go-librespot[1545]: time="2025-03-15T19:45:52+01:00" level=debug msg="requested aes key for file faa5144006c0b86c4d86e23368bd2f7c1426ccf5, gid: 4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=debug msg="fetched first chunk of 15, total size is 7341677 bytes" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=info msg="loaded track \"ILIKEU - CAMOUFLY REMIX\" (paused: false, position: 0ms, duration: 166937ms, prefetched: false)" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=trace msg="scheduling prefetch in 137s" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:53 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4NAzeOi10pTqHlNvWxoWjA","name":"ILIKEU - CAMOUFLY REMIX","artist_names":["Machinedrum","Duckwrth","camoufly"],"album_name":"3RMX82","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02088999b4ce8a7cc2a5ca6fe3","position":0,"duration":166937,"release_date":"year:2025 month:3 day:4","track_number":5,"disc_number":1}} Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:53 volumio go-librespot[1545]: time="2025-03-15T19:45:53+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:45:53 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4NAzeOi10pTqHlNvWxoWjA","play_origin":"playlist"}} Mar 15 19:45:53 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:53 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"ILIKEU - CAMOUFLY REMIX","artist":"Machinedrum, Duckwrth, camoufly","album":"3RMX82","albumart":"https://i.scdn.co/image/ab67616d00001e02088999b4ce8a7cc2a5ca6fe3","uri":"spotify:track:4NAzeOi10pTqHlNvWxoWjA","trackType":"spotify","seek":0,"duration":166,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:53 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:53 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:53 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:53 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:53 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (ILIKEU - CAMOUFLY REMIX) and artist (Machinedrum, Duckwrth, camoufly) passed on explicitly Mar 15 19:45:53 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:53 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:53 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"ILIKEU - CAMOUFLY REMIX","artist":"Machinedrum, Duckwrth, camoufly","album":"3RMX82","albumart":"https://i.scdn.co/image/ab67616d00001e02088999b4ce8a7cc2a5ca6fe3","uri":"spotify:track:4NAzeOi10pTqHlNvWxoWjA","trackType":"spotify","seek":0,"duration":166,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:53 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:53 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:53 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:53 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="seek track to 69022ms" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="fetched chunk 5/14, size: 524288" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=trace msg="seek to 69022ms (diff: 129ms, samples: 3043870, bytes: 3124197)" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="fetched chunk 7/14, size: 524288" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="fetched chunk 6/14, size: 524288" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="fetched chunk 8/14, size: 524288" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=trace msg="scheduling prefetch in 68s" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:55 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:4NAzeOi10pTqHlNvWxoWjA","position":69022,"duration":166937,"play_origin":"playlist"}} Mar 15 19:45:55 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:55 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"ILIKEU - CAMOUFLY REMIX","artist":"Machinedrum, Duckwrth, camoufly","album":"3RMX82","albumart":"https://i.scdn.co/image/ab67616d00001e02088999b4ce8a7cc2a5ca6fe3","uri":"spotify:track:4NAzeOi10pTqHlNvWxoWjA","trackType":"spotify","seek":69022,"duration":166,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:55 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:55 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:55 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:55 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:55 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:55 volumio go-librespot[1545]: time="2025-03-15T19:45:55+01:00" level=debug msg="fetched chunk 9/14, size: 524288" uri="spotify:track:4NAzeOi10pTqHlNvWxoWjA" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:45:57 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","play_origin":"playlist"}} Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="selected format OGG_VORBIS_320 (3234ee1701b8306324a60675ef988a660e9cbcb4)" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="requested aes key for file 3234ee1701b8306324a60675ef988a660e9cbcb4, gid: 2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="fetched first chunk of 18, total size is 9340280 bytes" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=info msg="loaded track \"Turu Uku\" (paused: false, position: 0ms, duration: 263145ms, prefetched: false)" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=trace msg="scheduling prefetch in 233s" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:45:57 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","name":"Turu Uku","artist_names":["Cruzloma"],"album_name":"Mitos \u0026 Ritos","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02bbc43d24857f3f00fe994aad","position":0,"duration":263145,"release_date":"year:2024 month:5 day:24","track_number":6,"disc_number":1}} Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:45:57 volumio go-librespot[1545]: time="2025-03-15T19:45:57+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:45:57 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","play_origin":"playlist"}} Mar 15 19:45:57 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:57 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Turu Uku","artist":"Cruzloma","album":"Mitos & Ritos","albumart":"https://i.scdn.co/image/ab67616d00001e02bbc43d24857f3f00fe994aad","uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","trackType":"spotify","seek":0,"duration":263,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:57 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:57 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:57 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:57 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:57 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (Turu Uku) and artist (Cruzloma) passed on explicitly Mar 15 19:45:57 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:58 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:45:58 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Turu Uku","artist":"Cruzloma","album":"Mitos & Ritos","albumart":"https://i.scdn.co/image/ab67616d00001e02bbc43d24857f3f00fe994aad","uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","trackType":"spotify","seek":1000,"duration":263,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:45:58 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:45:58 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:45:58 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:45:58 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:45:58 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:45:58 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Turu Uku","url":"https://www.last.fm/music/Cruzloma/_/Turu+Uku","duration":"263000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"32","playcount":"75","artist":{"name":"Cruzloma","url":"https://www.last.fm/music/Cruzloma"},"album":{"artist":"Cruzloma","title":"Mitos & Ritos","url":"https://www.last.fm/music/Cruzloma/Mitos+&+Ritos","image":[{"#":"https://lastfm.freetls.fastly.net/i/u/34s/cebb34bab7096cfd585bcf8b7a5714d9.png","@":{"size":"small"}},{"#":"https://lastfm.freetls.fastly.net/i/u/64s/cebb34bab7096cfd585bcf8b7a5714d9.png","@":{"size":"medium"}},{"#":"https://lastfm.freetls.fastly.net/i/u/174s/cebb34bab7096cfd585bcf8b7a5714d9.png","@":{"size":"large"}},{"#":"https://lastfm.freetls.fastly.net/i/u/300x300/cebb34bab7096cfd585bcf8b7a5714d9.png","@":{"size":"extralarge"}}]},"userplaycount":"0","userloved":"0","toptags":""}} Mar 15 19:45:58 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"ILIKEU - CAMOUFLY REMIX","url":"https://www.last.fm/music/Machinedrum,+Duckwrth,+camoufly/_/ILIKEU+-+CAMOUFLY+REMIX","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"13","playcount":"26","artist":{"name":"Machinedrum, Duckwrth, camoufly","url":"https://www.last.fm/music/Machinedrum,+Duckwrth,+camoufly"},"userplaycount":"0","userloved":"0","toptags":""}} Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=debug msg="seek track to 117234ms" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=trace msg="seek to 117234ms (diff: 117ms, samples: 5170019, bytes: 4098241)" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=debug msg="fetched chunk 8/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=debug msg="fetched chunk 10/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=debug msg="fetched chunk 9/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=trace msg="scheduling prefetch in 116s" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:46:00 volumio go-librespot[1545]: time="2025-03-15T19:46:00+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:46:00 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","position":117234,"duration":263145,"play_origin":"playlist"}} Mar 15 19:46:00 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:00 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Turu Uku","artist":"Cruzloma","album":"Mitos & Ritos","albumart":"https://i.scdn.co/image/ab67616d00001e02bbc43d24857f3f00fe994aad","uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","trackType":"spotify","seek":117234,"duration":263,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:00 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:00 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:00 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:46:00 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:00 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:02 volumio go-librespot[1545]: time="2025-03-15T19:46:02+01:00" level=trace msg="sent dealer ping" Mar 15 19:46:02 volumio go-librespot[1545]: time="2025-03-15T19:46:02+01:00" level=trace msg="received dealer pong" Mar 15 19:46:02 volumio go-librespot[1545]: time="2025-03-15T19:46:02+01:00" level=debug msg="fetched chunk 11/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=debug msg="handling seek_to player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=debug msg="seek track to 172900ms" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=trace msg="seek to 172900ms (diff: 95ms, samples: 7624890, bytes: 6078529)" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=debug msg="fetched chunk 12/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=debug msg="fetched chunk 14/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=debug msg="fetched chunk 13/17, size: 524288" uri="spotify:track:2dtnCqeHjUAK3A2bMSzYa3" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=trace msg="scheduling prefetch in 60s" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=trace msg="emitting websocket event: seek" Mar 15 19:46:03 volumio go-librespot[1545]: time="2025-03-15T19:46:03+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:46:03 volumio volumio[1091]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","position":172900,"duration":263145,"play_origin":"playlist"}} Mar 15 19:46:03 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:03 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Turu Uku","artist":"Cruzloma","album":"Mitos & Ritos","albumart":"https://i.scdn.co/image/ab67616d00001e02bbc43d24857f3f00fe994aad","uri":"spotify:track:2dtnCqeHjUAK3A2bMSzYa3","trackType":"spotify","seek":172900,"duration":263,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:03 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:03 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:03 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:46:03 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:03 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2rmTaigCEjze3R7qpe9rWc" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:46:05 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2rmTaigCEjze3R7qpe9rWc","play_origin":"playlist"}} Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="selected format OGG_VORBIS_320 (1fa994ad7ace7fa42bac9c699d2d2b65cc20d90e)" uri="spotify:track:2rmTaigCEjze3R7qpe9rWc" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="requested aes key for file 1fa994ad7ace7fa42bac9c699d2d2b65cc20d90e, gid: 2rmTaigCEjze3R7qpe9rWc" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="fetched first chunk of 14, total size is 7082137 bytes" uri="spotify:track:2rmTaigCEjze3R7qpe9rWc" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=info msg="loaded track \"Oh No\" (paused: false, position: 0ms, duration: 169668ms, prefetched: false)" uri="spotify:track:2rmTaigCEjze3R7qpe9rWc" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:2rmTaigCEjze3R7qpe9rWc" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:2rmTaigCEjze3R7qpe9rWc" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:2rmTaigCEjze3R7qpe9rWc" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=trace msg="scheduling prefetch in 140s" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:46:05 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2rmTaigCEjze3R7qpe9rWc","name":"Oh No","artist_names":["1tbsp"],"album_name":"megacity1000","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02bd4dbcb381a7143a20452c1a","position":0,"duration":169668,"release_date":"year:2024 month:8 day:29","track_number":6,"disc_number":1}} Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:05 volumio go-librespot[1545]: time="2025-03-15T19:46:05+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:46:05 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2rmTaigCEjze3R7qpe9rWc","play_origin":"playlist"}} Mar 15 19:46:05 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:05 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Oh No","artist":"1tbsp","album":"megacity1000","albumart":"https://i.scdn.co/image/ab67616d00001e02bd4dbcb381a7143a20452c1a","uri":"spotify:track:2rmTaigCEjze3R7qpe9rWc","trackType":"spotify","seek":0,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:05 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:05 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:05 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:46:05 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:05 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (Oh No) and artist (1tbsp) passed on explicitly Mar 15 19:46:05 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:06 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Oh No","url":"https://www.last.fm/music/1tbsp/_/Oh+No","duration":"169000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"10633","playcount":"38532","artist":{"name":"1tbsp","url":"https://www.last.fm/music/1tbsp"},"album":{"artist":"1tbsp","title":"Oh No","url":"https://www.last.fm/music/1tbsp/Oh+No","image":[{"#":"https://lastfm.freetls.fastly.net/i/u/34s/f0850e737b80edfaa8d922b8b615485d.png","@":{"size":"small"}},{"#":"https://lastfm.freetls.fastly.net/i/u/64s/f0850e737b80edfaa8d922b8b615485d.png","@":{"size":"medium"}},{"#":"https://lastfm.freetls.fastly.net/i/u/174s/f0850e737b80edfaa8d922b8b615485d.png","@":{"size":"large"}},{"#":"https://lastfm.freetls.fastly.net/i/u/300x300/f0850e737b80edfaa8d922b8b615485d.png","@":{"size":"extralarge"}}]},"userplaycount":"0","userloved":"0","toptags":""}} Mar 15 19:46:06 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:06 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Oh No","artist":"1tbsp","album":"megacity1000","albumart":"https://i.scdn.co/image/ab67616d00001e02bd4dbcb381a7143a20452c1a","uri":"spotify:track:2rmTaigCEjze3R7qpe9rWc","trackType":"spotify","seek":0,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:06 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:06 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:06 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:06 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2SK9jMkla2AgRxT9uOdFvQ" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2SK9jMkla2AgRxT9uOdFvQ","play_origin":"playlist"}} Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="selected format OGG_VORBIS_320 (c958077f9d2990cf2489127efdf056a370ed530d)" uri="spotify:track:2SK9jMkla2AgRxT9uOdFvQ" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="requested aes key for file c958077f9d2990cf2489127efdf056a370ed530d, gid: 2SK9jMkla2AgRxT9uOdFvQ" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="fetched first chunk of 29, total size is 14810099 bytes" uri="spotify:track:2SK9jMkla2AgRxT9uOdFvQ" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=info msg="loaded track \"I SAID\" (paused: false, position: 0ms, duration: 390762ms, prefetched: false)" uri="spotify:track:2SK9jMkla2AgRxT9uOdFvQ" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="fetched chunk 1/28, size: 524288" uri="spotify:track:2SK9jMkla2AgRxT9uOdFvQ" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="fetched chunk 3/28, size: 524288" uri="spotify:track:2SK9jMkla2AgRxT9uOdFvQ" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=trace msg="scheduling prefetch in 361s" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2SK9jMkla2AgRxT9uOdFvQ","name":"I SAID","artist_names":["Paurro"],"album_name":"I SAID","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c9938e041196a44b79525e4d","position":0,"duration":390762,"release_date":"year:2025 month:1 day:6","track_number":1,"disc_number":1}} Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="fetched chunk 2/28, size: 524288" uri="spotify:track:2SK9jMkla2AgRxT9uOdFvQ" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:07 volumio go-librespot[1545]: time="2025-03-15T19:46:07+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2SK9jMkla2AgRxT9uOdFvQ","play_origin":"playlist"}} Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"I SAID","artist":"Paurro","album":"I SAID","albumart":"https://i.scdn.co/image/ab67616d00001e02c9938e041196a44b79525e4d","uri":"spotify:track:2SK9jMkla2AgRxT9uOdFvQ","trackType":"spotify","seek":0,"duration":390,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:07 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:07 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:07 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:46:07 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:07 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (I SAID) and artist (Paurro) passed on explicitly Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"I SAID","artist":"Paurro","album":"I SAID","albumart":"https://i.scdn.co/image/ab67616d00001e02c9938e041196a44b79525e4d","uri":"spotify:track:2SK9jMkla2AgRxT9uOdFvQ","trackType":"spotify","seek":0,"duration":390,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:07 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:07 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:07 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:07 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:08 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"I SAID","url":"https://www.last.fm/music/Paurro/_/I+SAID","duration":"390000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"55","playcount":"99","artist":{"name":"Paurro","url":"https://www.last.fm/music/Paurro"},"album":{"artist":"Various Artists","title":"Grounders","url":"https://www.last.fm/music/Various+Artists/Grounders","image":[{"@":{"size":"small"}},{"@":{"size":"medium"}},{"@":{"size":"large"}},{"@":{"size":"extralarge"}}]},"userplaycount":"0","userloved":"0","toptags":""}} Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5BeppTbYNEBgVi22rJfEHk","play_origin":"playlist"}} Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="selected format OGG_VORBIS_320 (994c8d2c98c000d3ac5c27427687385cfde69647)" uri="spotify:track:5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="requested aes key for file 994c8d2c98c000d3ac5c27427687385cfde69647, gid: 5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="fetched first chunk of 39, total size is 20326268 bytes" uri="spotify:track:5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=info msg="loaded track \"No Mantra\" (paused: false, position: 1ms, duration: 458338ms, prefetched: false)" uri="spotify:track:5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="fetched chunk 2/38, size: 524288" uri="spotify:track:5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=trace msg="scheduling prefetch in 428s" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5BeppTbYNEBgVi22rJfEHk","name":"No Mantra","artist_names":["Tibi Dabo"],"album_name":"La Dorada","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e33ce4090cd562ca48e00d7b","position":1,"duration":458338,"release_date":"year:2018 month:8 day:17","track_number":2,"disc_number":1}} Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="fetched chunk 3/38, size: 524288" uri="spotify:track:5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="fetched chunk 1/38, size: 524288" uri="spotify:track:5BeppTbYNEBgVi22rJfEHk" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:09 volumio go-librespot[1545]: time="2025-03-15T19:46:09+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5BeppTbYNEBgVi22rJfEHk","play_origin":"playlist"}} Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"No Mantra","artist":"Tibi Dabo","album":"La Dorada","albumart":"https://i.scdn.co/image/ab67616d00001e02e33ce4090cd562ca48e00d7b","uri":"spotify:track:5BeppTbYNEBgVi22rJfEHk","trackType":"spotify","seek":1,"duration":458,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:09 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:09 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:09 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:46:09 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:09 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (No Mantra) and artist (Tibi Dabo) passed on explicitly Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"No Mantra","artist":"Tibi Dabo","album":"La Dorada","albumart":"https://i.scdn.co/image/ab67616d00001e02e33ce4090cd562ca48e00d7b","uri":"spotify:track:5BeppTbYNEBgVi22rJfEHk","trackType":"spotify","seek":1,"duration":458,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:09 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:09 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:09 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:09 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:10 volumio go-librespot[1545]: time="2025-03-15T19:46:10+01:00" level=debug msg="handling play player command from 2687643768002a2e4a3063469e6443dc006accf6" Mar 15 19:46:10 volumio go-librespot[1545]: time="2025-03-15T19:46:10+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:46:10 volumio go-librespot[1545]: time="2025-03-15T19:46:10+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DWWye7T9y0Pwf" Mar 15 19:46:10 volumio go-librespot[1545]: time="2025-03-15T19:46:10+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4J8IH4SQ1Luk6NufgRs7zt" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=trace msg="emitting websocket event: will_play" Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4J8IH4SQ1Luk6NufgRs7zt","play_origin":"playlist"}} Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="selected format OGG_VORBIS_320 (1185fc01e8323dc45d8937d820f8f623d5a7598e)" uri="spotify:track:4J8IH4SQ1Luk6NufgRs7zt" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="requested aes key for file 1185fc01e8323dc45d8937d820f8f623d5a7598e, gid: 4J8IH4SQ1Luk6NufgRs7zt" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="fetched first chunk of 36, total size is 18480136 bytes" uri="spotify:track:4J8IH4SQ1Luk6NufgRs7zt" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=info msg="loaded track \"Fusin'\" (paused: false, position: 0ms, duration: 466427ms, prefetched: false)" uri="spotify:track:4J8IH4SQ1Luk6NufgRs7zt" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="fetched chunk 1/35, size: 524288" uri="spotify:track:4J8IH4SQ1Luk6NufgRs7zt" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="fetched chunk 2/35, size: 524288" uri="spotify:track:4J8IH4SQ1Luk6NufgRs7zt" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=trace msg="scheduling prefetch in 436s" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=trace msg="emitting websocket event: metadata" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="sending successful reply for dealer request" Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4J8IH4SQ1Luk6NufgRs7zt","name":"Fusin'","artist_names":["Technasia"],"album_name":"Fusin'","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024fbb01b2e8d1e8772eace838","position":0,"duration":466427,"release_date":"year:2003 month:6 day:19","track_number":1,"disc_number":1}} Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="fetched chunk 3/35, size: 524288" uri="spotify:track:4J8IH4SQ1Luk6NufgRs7zt" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 15 19:46:11 volumio go-librespot[1545]: time="2025-03-15T19:46:11+01:00" level=trace msg="emitting websocket event: playing" Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4J8IH4SQ1Luk6NufgRs7zt","play_origin":"playlist"}} Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Fusin'","artist":"Technasia","album":"Fusin'","albumart":"https://i.scdn.co/image/ab67616d00001e024fbb01b2e8d1e8772eace838","uri":"spotify:track:4J8IH4SQ1Luk6NufgRs7zt","trackType":"spotify","seek":0,"duration":466,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:11 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:11 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:11 volumio volumio[1091]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 15 19:46:11 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:11 volumio volumio[1091]: info: [LastFM] Current track has sufficient metadata: title (Fusin') and artist (Technasia) passed on explicitly Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:11 volumio volumio[1091]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Fusin'","mbid":"f6028588-bf01-4654-a4de-abd8df7e3118","url":"https://www.last.fm/music/Technasia/_/Fusin%27","duration":"224000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"380","playcount":"1255","artist":{"name":"Technasia","mbid":"e0d60456-7353-4013-b8e2-966b1a2e21c4","url":"https://www.last.fm/music/Technasia"},"album":{"@":{"position":"1"},"artist":"Technasia","title":"Fusin'","mbid":"617c438e-c912-4ae5-9f56-c222c1361ec2","url":"https://www.last.fm/music/Technasia/Fusin%27","image":[{"#":"https://lastfm.freetls.fastly.net/i/u/34s/19b620e97e0c4c6c8d122d2bd64febb9.png","@":{"size":"small"}},{"#":"https://lastfm.freetls.fastly.net/i/u/64s/19b620e97e0c4c6c8d122d2bd64febb9.png","@":{"size":"medium"}},{"#":"https://lastfm.freetls.fastly.net/i/u/174s/19b620e97e0c4c6c8d122d2bd64febb9.png","@":{"size":"large"}},{"#":"https://lastfm.freetls.fastly.net/i/u/300x300/19b620e97e0c4c6c8d122d2bd64febb9.png","@":{"size":"extralarge"}}]},"userplaycount":"0","userloved":"0","toptags":{"tag":{"name":"techno","url":"https://www.last.fm/tag/techno"}}}} Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: PUSH STATE SPOTIFY Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: {"status":"play","service":"spop","title":"Fusin'","artist":"Technasia","album":"Fusin'","albumart":"https://i.scdn.co/image/ab67616d00001e024fbb01b2e8d1e8772eace838","uri":"spotify:track:4J8IH4SQ1Luk6NufgRs7zt","trackType":"spotify","seek":0,"duration":466,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Mar 15 19:46:11 volumio volumio[1091]: info: CoreCommandRouter::servicePushState Mar 15 19:46:11 volumio volumio[1091]: info: CoreStateMachine::pushState Mar 15 19:46:11 volumio volumio[1091]: info: CoreCommandRouter::volumioPushState Mar 15 19:46:11 volumio volumio[1091]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Mar 15 19:46:12 volumio volumio[1091]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 15 19:46:12 volumio volumio[1091]: TypeError: Cannot read property '@' of null Mar 15 19:46:12 volumio volumio[1091]: at Object.callback (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:342:14) Mar 15 19:46:12 volumio volumio[1091]: at /data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:60:13 Mar 15 19:46:12 volumio volumio[1091]: at Parser. (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:304:18) Mar 15 19:46:12 volumio volumio[1091]: at Parser.emit (events.js:400:28) Mar 15 19:46:12 volumio volumio[1091]: at Parser.exports.Parser.Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:314:16) Mar 15 19:46:12 volumio volumio[1091]: at Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:5:59) Mar 15 19:46:12 volumio volumio[1091]: at IncomingMessage. (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:58:14) Mar 15 19:46:12 volumio volumio[1091]: at IncomingMessage.emit (events.js:412:35) Mar 15 19:46:12 volumio volumio[1091]: at endReadableNT (internal/streams/readable.js:1333:12) Mar 15 19:46:12 volumio volumio[1091]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Mar 15 19:46:12 volumio volumio[1091]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 15 19:46:13 volumio sudo[31602]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-15 19:45 Mar 15 19:46:13 volumio sudo[31602]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 07:25:16 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="66c567362bdbb3dc1644a18f7879afe7"