-- Logs begin at Thu 2025-06-12 07:03:01 CEST, end at Fri 2025-06-13 13:37:09 CEST. -- Jun 13 13:36:02 altanen volumio[1040]: info: CoreCommandRouter::volumioGetState Jun 13 13:36:05 altanen go-librespot[1245]: time="2025-06-13T13:36:05+02:00" level=debug msg="prefetching next track" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:05 altanen go-librespot[1245]: time="2025-06-13T13:36:05+02:00" level=debug msg="selected format OGG_VORBIS_320 (390530de3907b9919f1cc89a347967512434db04)" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:05 altanen go-librespot[1245]: time="2025-06-13T13:36:05+02:00" level=debug msg="requested aes key for file 390530de3907b9919f1cc89a347967512434db04, gid: 2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:05 altanen go-librespot[1245]: time="2025-06-13T13:36:05+02:00" level=debug msg="fetched first chunk of 15, total size is 7688452 bytes" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:05 altanen go-librespot[1245]: time="2025-06-13T13:36:05+02:00" level=info msg="prefetched track \"Rollercoaster\" (duration: 180720ms)" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:05 altanen go-librespot[1245]: time="2025-06-13T13:36:05+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:05 altanen go-librespot[1245]: time="2025-06-13T13:36:05+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:05 altanen go-librespot[1245]: time="2025-06-13T13:36:05+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:12 altanen volumio[1040]: info: CoreCommandRouter::volumioGetState Jun 13 13:36:12 altanen volumio[1040]: info: Listing playlists Jun 13 13:36:12 altanen volumio[1040]: info: Listing playlists Jun 13 13:36:20 altanen go-librespot[1245]: time="2025-06-13T13:36:20+02:00" level=trace msg="sent dealer ping" Jun 13 13:36:20 altanen go-librespot[1245]: time="2025-06-13T13:36:20+02:00" level=trace msg="received dealer pong" Jun 13 13:36:22 altanen volumio[1040]: info: CoreCommandRouter::volumioGetState Jun 13 13:36:32 altanen volumio[1040]: info: CoreCommandRouter::volumioGetState Jun 13 13:36:32 altanen volumio[1040]: info: Listing playlists Jun 13 13:36:32 altanen volumio[1040]: info: Listing playlists Jun 13 13:36:34 altanen go-librespot[1245]: time="2025-06-13T13:36:34+02:00" level=trace msg="emitting websocket event: not_playing" Jun 13 13:36:34 altanen go-librespot[1245]: time="2025-06-13T13:36:34+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:34 altanen volumio[1040]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:5KW5BO3fwejLvTIqFOe6hS","play_origin":"playlist/ondemand"}} Jun 13 13:36:34 altanen volumio[1040]: error: Failed to decode event: not_playing Jun 13 13:36:34 altanen go-librespot[1245]: time="2025-06-13T13:36:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:34 altanen go-librespot[1245]: time="2025-06-13T13:36:34+02:00" level=trace msg="emitting websocket event: will_play" Jun 13 13:36:34 altanen go-librespot[1245]: time="2025-06-13T13:36:34+02:00" level=info msg="loaded track \"Rollercoaster\" (paused: false, position: 0ms, duration: 180720ms, prefetched: true)" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:34 altanen volumio[1040]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","play_origin":"playlist/ondemand"}} Jun 13 13:36:35 altanen go-librespot[1245]: time="2025-06-13T13:36:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:35 altanen go-librespot[1245]: time="2025-06-13T13:36:35+02:00" level=trace msg="scheduling prefetch in 151s" Jun 13 13:36:35 altanen go-librespot[1245]: time="2025-06-13T13:36:35+02:00" level=trace msg="emitting websocket event: metadata" Jun 13 13:36:35 altanen volumio[1040]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","name":"Rollercoaster","artist_names":["Dolly Style"],"album_name":"Rollercoaster","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","position":0,"duration":180720,"release_date":"year:2016 month:2 day:28","track_number":1,"disc_number":1}} Jun 13 13:36:35 altanen go-librespot[1245]: time="2025-06-13T13:36:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:35 altanen go-librespot[1245]: time="2025-06-13T13:36:35+02:00" level=trace msg="emitting websocket event: playing" Jun 13 13:36:35 altanen volumio[1040]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","play_origin":"playlist/ondemand"}} Jun 13 13:36:35 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:36:35 altanen volumio[1040]: SPOTIFY: {"status":"play","service":"spop","title":"Rollercoaster","artist":"Dolly Style","album":"Rollercoaster","albumart":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","trackType":"spotify","seek":0,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:35 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:36:35 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:36:35 altanen volumio[1040]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 13:36:35 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:36:35 altanen volumio[1040]: info: [LastFM] Current track has sufficient metadata: title (Rollercoaster) and artist (Dolly Style) passed on explicitly Jun 13 13:36:35 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:36:35 altanen volumio[1040]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Rollercoaster","url":"https://www.last.fm/music/Dolly+Style/_/Rollercoaster","duration":"180000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"7327","playcount":"54006","artist":{"name":"Dolly Style","url":"https://www.last.fm/music/Dolly+Style"},"album":{"artist":"Various Artists","title":"Melodifestivalen 2016","url":"https://www.last.fm/music/Various+Artists/Melodifestivalen+2016","image":[{"#":"https://lastfm.freetls.fastly.net/i/u/34s/603e1198cb58e22bf477c19afdd53a0b.png","@":{"size":"small"}},{"#":"https://lastfm.freetls.fastly.net/i/u/64s/603e1198cb58e22bf477c19afdd53a0b.png","@":{"size":"medium"}},{"#":"https://lastfm.freetls.fastly.net/i/u/174s/603e1198cb58e22bf477c19afdd53a0b.png","@":{"size":"large"}},{"#":"https://lastfm.freetls.fastly.net/i/u/300x300/603e1198cb58e22bf477c19afdd53a0b.png","@":{"size":"extralarge"}}]},"userplaycount":"6","userloved":"0","toptags":{"tag":[{"name":"pop","url":"https://www.last.fm/tag/pop"},{"name":"swedish","url":"https://www.last.fm/tag/swedish"},{"name":"melodifestivalen","url":"https://www.last.fm/tag/melodifestivalen"},{"name":"svenska","url":"https://www.last.fm/tag/svenska"}]}}} Jun 13 13:36:35 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:36:35 altanen volumio[1040]: SPOTIFY: {"status":"play","service":"spop","title":"Rollercoaster","artist":"Dolly Style","album":"Rollercoaster","albumart":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","trackType":"spotify","seek":1000,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:35 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:36:35 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:36:35 altanen volumio[1040]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 13:36:35 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:36:35 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:36:36 altanen go-librespot[1245]: time="2025-06-13T13:36:36+02:00" level=trace msg="received accesspoint ping" Jun 13 13:36:36 altanen go-librespot[1245]: time="2025-06-13T13:36:36+02:00" level=trace msg="received accesspoint pong ack" Jun 13 13:36:39 altanen volumio[1040]: info: Jun 13 13:36:39 altanen volumio[1040]: ---------------------------- Client requests Volumio pause Jun 13 13:36:39 altanen volumio[1040]: info: CoreCommandRouter::volumioPause Jun 13 13:36:39 altanen volumio[1040]: info: CoreStateMachine::pause Jun 13 13:36:39 altanen volumio[1040]: info: CoreStateMachine::stPlaybackTimer Jun 13 13:36:39 altanen volumio[1040]: info: CoreStateMachine::servicePause Jun 13 13:36:39 altanen volumio[1040]: info: CoreCommandRouter::servicePause Jun 13 13:36:39 altanen volumio[1040]: info: Spotify Received pause Jun 13 13:36:39 altanen volumio[1040]: SPOTIFY: SPOTIFY PAUSE Jun 13 13:36:39 altanen volumio[1040]: SPOTIFY: {"status":"play","title":"Rollercoaster","artist":"Dolly Style","album":"Rollercoaster","albumart":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","trackType":"spotify","codec":"ogg","seek":1000,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":44,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Jun 13 13:36:39 altanen volumio[1040]: info: Sending Spotify command to local API: /player/pause Jun 13 13:36:39 altanen go-librespot[1245]: time="2025-06-13T13:36:39+02:00" level=debug msg="pause track at 4120ms" Jun 13 13:36:39 altanen volumio[1040]: info: CoreCommandRouter::volumioGetState Jun 13 13:36:39 altanen go-librespot[1245]: time="2025-06-13T13:36:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:39 altanen go-librespot[1245]: time="2025-06-13T13:36:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:39 altanen go-librespot[1245]: time="2025-06-13T13:36:39+02:00" level=trace msg="emitting websocket event: paused" Jun 13 13:36:39 altanen volumio[1040]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","play_origin":"playlist/ondemand"}} Jun 13 13:36:39 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:36:39 altanen volumio[1040]: SPOTIFY: {"status":"pause","service":"spop","title":"Rollercoaster","artist":"Dolly Style","album":"Rollercoaster","albumart":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","trackType":"spotify","seek":5000,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:39 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:36:39 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:36:39 altanen volumio[1040]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 13:36:39 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:36:39 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:36:42 altanen volumio[1040]: info: CoreCommandRouter::volumioGetState Jun 13 13:36:44 altanen volumio[1040]: info: Jun 13 13:36:44 altanen volumio[1040]: ---------------------------- Client requests Volumio play Jun 13 13:36:44 altanen volumio[1040]: info: CoreCommandRouter::volumioPlay Jun 13 13:36:44 altanen volumio[1040]: info: CoreStateMachine::play index undefined Jun 13 13:36:44 altanen volumio[1040]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 13:36:44 altanen volumio[1040]: info: CorePlayQueue::getTrack 0 Jun 13 13:36:50 altanen go-librespot[1245]: time="2025-06-13T13:36:50+02:00" level=trace msg="sent dealer ping" Jun 13 13:36:50 altanen go-librespot[1245]: time="2025-06-13T13:36:50+02:00" level=trace msg="received dealer pong" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="handling resume player command from 926daf0689ec9ccfad7f2318f0b9e136e9652a3e" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=trace msg="seek to 4120ms (diff: 105ms, samples: 181692, bytes: 186175)" uri="spotify:track:2quKrwqzcvfD0RLcP2cVSq" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="resume track at 4015ms" Jun 13 13:36:51 altanen volumio[1040]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jun 13 13:36:51 altanen volumio[1040]: info: FusionDsp - ---- read samplerate from file: 44100 Jun 13 13:36:51 altanen volumio[1040]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jun 13 13:36:51 altanen volumio[1040]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=trace msg="scheduling prefetch in 146s" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="sending successful reply for dealer request" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=trace msg="emitting websocket event: playing" Jun 13 13:36:51 altanen volumio[1040]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","play_origin":"playlist/ondemand"}} Jun 13 13:36:51 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:36:51 altanen volumio[1040]: SPOTIFY: {"status":"play","service":"spop","title":"Rollercoaster","artist":"Dolly Style","album":"Rollercoaster","albumart":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","trackType":"spotify","seek":5000,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:51 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:36:51 altanen volumio[1040]: info: CorePlayQueue::getTrack 0 Jun 13 13:36:51 altanen volumio[1040]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Rollercoaster","artist":"Dolly Style","album":"Rollercoaster","albumart":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","trackType":"spotify","seek":5000,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:51 altanen volumio[1040]: verbose: CURRENT POSITION 0 Jun 13 13:36:51 altanen volumio[1040]: info: CoreStateMachine::syncState stateService play Jun 13 13:36:51 altanen volumio[1040]: info: CoreStateMachine::syncState currentStatus pause Jun 13 13:36:51 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:36:51 altanen volumio[1040]: info: CorePlayQueue::getTrack 0 Jun 13 13:36:51 altanen volumio[1040]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 13:36:51 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:36:51 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:36:51 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:36:51 altanen volumio[1040]: SPOTIFY: {"status":"play","service":"spop","title":"Rollercoaster","artist":"Dolly Style","album":"Rollercoaster","albumart":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","trackType":"spotify","seek":5000,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:51 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:36:51 altanen volumio[1040]: info: CorePlayQueue::getTrack 0 Jun 13 13:36:51 altanen volumio[1040]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Rollercoaster","artist":"Dolly Style","album":"Rollercoaster","albumart":"https://i.scdn.co/image/ab67616d00001e02a5cc2b794e5c6f0d11f86924","uri":"spotify:track:2quKrwqzcvfD0RLcP2cVSq","trackType":"spotify","seek":5000,"duration":180,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:51 altanen volumio[1040]: verbose: CURRENT POSITION 0 Jun 13 13:36:51 altanen volumio[1040]: info: CoreStateMachine::syncState stateService play Jun 13 13:36:51 altanen volumio[1040]: info: CoreStateMachine::syncState currentStatus play Jun 13 13:36:51 altanen volumio[1040]: info: Received an update from plugin. extracting info from payload Jun 13 13:36:51 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:36:51 altanen volumio[1040]: info: CorePlayQueue::getTrack 0 Jun 13 13:36:51 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:36:51 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:36:51 altanen volumio[1040]: info: CorePlayQueue::getTrack 0 Jun 13 13:36:51 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:36:51 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:36:51 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="handling skip_next player command from 926daf0689ec9ccfad7f2318f0b9e136e9652a3e" Jun 13 13:36:51 altanen go-librespot[1245]: time="2025-06-13T13:36:51+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=trace msg="emitting websocket event: will_play" Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4PWUgGyBVJSKq4w8A6eG1H","play_origin":"playlist/ondemand"}} Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="selected format OGG_VORBIS_320 (0fef6781b64e9009149765b361230fec26cc8c1d)" uri="spotify:track:4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="requested aes key for file 0fef6781b64e9009149765b361230fec26cc8c1d, gid: 4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:36:52 altanen volumio[1040]: info: CoreCommandRouter::volumioGetState Jun 13 13:36:52 altanen volumio[1040]: info: CorePlayQueue::getTrack 0 Jun 13 13:36:52 altanen volumio[1040]: info: Listing playlists Jun 13 13:36:52 altanen volumio[1040]: info: Listing playlists Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="fetched first chunk of 16, total size is 8148588 bytes" uri="spotify:track:4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=info msg="loaded track \"Händerna upp\" (paused: false, position: 0ms, duration: 181290ms, prefetched: false)" uri="spotify:track:4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=trace msg="scheduling prefetch in 151s" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=trace msg="emitting websocket event: metadata" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="sending successful reply for dealer request" Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4PWUgGyBVJSKq4w8A6eG1H","name":"Händerna upp","artist_names":["Duran \u0026 Mollan"],"album_name":"Rymdraket","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b822d45f64cde5b7b3f6c94f","position":0,"duration":181290,"release_date":"year:2014 month:6 day:30","track_number":4,"disc_number":1}} Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:36:52 altanen go-librespot[1245]: time="2025-06-13T13:36:52+02:00" level=trace msg="emitting websocket event: playing" Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4PWUgGyBVJSKq4w8A6eG1H","play_origin":"playlist/ondemand"}} Jun 13 13:36:52 altanen volumio[1040]: info: Spotify is playing in volatile mode Jun 13 13:36:52 altanen volumio[1040]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: UNSET VOLATILE Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":44,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":null,"repeatSingle":false,"consume":false} Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: {"status":"play","service":"spop","title":"Händerna upp","artist":"Duran & Mollan","album":"Rymdraket","albumart":"https://i.scdn.co/image/ab67616d00001e02b822d45f64cde5b7b3f6c94f","uri":"spotify:track:4PWUgGyBVJSKq4w8A6eG1H","trackType":"spotify","seek":0,"duration":181,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:52 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:36:52 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:36:52 altanen volumio[1040]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 13:36:52 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:36:52 altanen volumio[1040]: info: [LastFM] Current track has sufficient metadata: title (Händerna upp) and artist (Duran & Mollan) passed on explicitly Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:36:52 altanen volumio[1040]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Händerna upp","url":"https://www.last.fm/music/Duran+&+Mollan/_/H%C3%A4nderna+upp","duration":"181000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"2811","playcount":"25987","artist":{"name":"Duran & Mollan","url":"https://www.last.fm/music/Duran+&+Mollan"},"album":{"artist":"Duran & Mollan","title":"Rymdraket","url":"https://www.last.fm/music/Duran+&+Mollan/Rymdraket","image":[{"@":{"size":"small"}},{"@":{"size":"medium"}},{"@":{"size":"large"}},{"@":{"size":"extralarge"}}]},"userplaycount":"37","userloved":"0","toptags":""}} Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: {"status":"play","service":"spop","title":"Händerna upp","artist":"Duran & Mollan","album":"Rymdraket","albumart":"https://i.scdn.co/image/ab67616d00001e02b822d45f64cde5b7b3f6c94f","uri":"spotify:track:4PWUgGyBVJSKq4w8A6eG1H","trackType":"spotify","seek":0,"duration":181,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:36:52 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:36:52 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:36:52 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:36:52 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:37:02 altanen volumio[1040]: info: CoreCommandRouter::volumioGetState Jun 13 13:37:03 altanen go-librespot[1245]: time="2025-06-13T13:37:03+02:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:4PWUgGyBVJSKq4w8A6eG1H" Jun 13 13:37:05 altanen go-librespot[1245]: time="2025-06-13T13:37:05+02:00" level=debug msg="handling play player command from 926daf0689ec9ccfad7f2318f0b9e136e9652a3e" Jun 13 13:37:05 altanen go-librespot[1245]: time="2025-06-13T13:37:05+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:4EUB78qaSE3CVRoQJ00Ra5" Jun 13 13:37:05 altanen go-librespot[1245]: time="2025-06-13T13:37:05+02:00" level=trace msg="fetched new page 0 with 88 items (list: 88)" uri="spotify:playlist:4EUB78qaSE3CVRoQJ00Ra5" Jun 13 13:37:05 altanen go-librespot[1245]: time="2025-06-13T13:37:05+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0AMoopn68aGAAaJ9qFXPnX" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=trace msg="emitting websocket event: will_play" Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0AMoopn68aGAAaJ9qFXPnX","play_origin":"playlist/ondemand"}} Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="selected format OGG_VORBIS_320 (af9604df9fc67ee311288d72f92eee0cca7274a8)" uri="spotify:track:0AMoopn68aGAAaJ9qFXPnX" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="requested aes key for file af9604df9fc67ee311288d72f92eee0cca7274a8, gid: 0AMoopn68aGAAaJ9qFXPnX" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="fetched first chunk of 15, total size is 7789343 bytes" uri="spotify:track:0AMoopn68aGAAaJ9qFXPnX" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=info msg="loaded track \"Lighter\" (paused: false, position: 0ms, duration: 175853ms, prefetched: false)" uri="spotify:track:0AMoopn68aGAAaJ9qFXPnX" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:0AMoopn68aGAAaJ9qFXPnX" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:0AMoopn68aGAAaJ9qFXPnX" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:0AMoopn68aGAAaJ9qFXPnX" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=trace msg="scheduling prefetch in 146s" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=trace msg="emitting websocket event: metadata" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="sending successful reply for dealer request" Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0AMoopn68aGAAaJ9qFXPnX","name":"Lighter","artist_names":["Kyle Alessandro"],"album_name":"Lighter","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0253dc26205f84d04f5409999a","position":0,"duration":175853,"release_date":"year:2025 month:1 day:24","track_number":1,"disc_number":1}} Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 13:37:06 altanen go-librespot[1245]: time="2025-06-13T13:37:06+02:00" level=trace msg="emitting websocket event: playing" Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0AMoopn68aGAAaJ9qFXPnX","play_origin":"playlist/ondemand"}} Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: {"status":"play","service":"spop","title":"Lighter","artist":"Kyle Alessandro","album":"Lighter","albumart":"https://i.scdn.co/image/ab67616d00001e0253dc26205f84d04f5409999a","uri":"spotify:track:0AMoopn68aGAAaJ9qFXPnX","trackType":"spotify","seek":1000,"duration":175,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:37:06 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:37:06 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:37:06 altanen volumio[1040]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 13:37:06 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:37:06 altanen volumio[1040]: info: [LastFM] Current track has sufficient metadata: title (Lighter) and artist (Kyle Alessandro) passed on explicitly Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: PUSH STATE SPOTIFY Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: {"status":"play","service":"spop","title":"Lighter","artist":"Kyle Alessandro","album":"Lighter","albumart":"https://i.scdn.co/image/ab67616d00001e0253dc26205f84d04f5409999a","uri":"spotify:track:0AMoopn68aGAAaJ9qFXPnX","trackType":"spotify","seek":1000,"duration":175,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 13 13:37:06 altanen volumio[1040]: info: CoreCommandRouter::servicePushState Jun 13 13:37:06 altanen volumio[1040]: info: CoreStateMachine::pushState Jun 13 13:37:06 altanen volumio[1040]: info: CoreCommandRouter::volumioPushState Jun 13 13:37:06 altanen volumio[1040]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Jun 13 13:37:09 altanen volumio[1040]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 13 13:37:09 altanen volumio[1040]: TypeError: Cannot read property '@' of null Jun 13 13:37:09 altanen volumio[1040]: at Object.callback (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:342:14) Jun 13 13:37:09 altanen volumio[1040]: at /data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:60:13 Jun 13 13:37:09 altanen volumio[1040]: at Parser. (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:304:18) Jun 13 13:37:09 altanen volumio[1040]: at Parser.emit (events.js:315:20) Jun 13 13:37:09 altanen volumio[1040]: at Parser.exports.Parser.Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:314:16) Jun 13 13:37:09 altanen volumio[1040]: at Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:5:59) Jun 13 13:37:09 altanen volumio[1040]: at IncomingMessage. (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:58:14) Jun 13 13:37:09 altanen volumio[1040]: at IncomingMessage.emit (events.js:327:22) Jun 13 13:37:09 altanen volumio[1040]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 13 13:37:09 altanen volumio[1040]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 13 13:37:09 altanen volumio[1040]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 13 13:37:09 altanen sudo[17417]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-13 13:36 Jun 13 13:37:09 altanen sudo[17417]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 04:52:53 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="a72866a0de4045751d03a035de6290e1"