Oct 11 13:59:37 living volumio[1291]: info: [1791737977239] [80s80s] Pushing the next song state Michael Jackson - Blood On the Dance Floor and getting next track. Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::servicePushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is2-ssl.mzstatic.com/image/thumb/Music114/v4/a3/45/e1/a345e1ff-78a8-d29b-b34f-85da553caddb/source/600x600bb.jpg","name":"Michael Jackson - Blood On the Dance Floor","title":"Blood On the Dance Floor","artist":"90s90s Hits","album":"","streaming":true,"disableUiControls":true,"duration":"235","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Oct 11 13:59:37 living volumio[1291]: verbose: CURRENT POSITION 0 Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::syncState stateService play Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::syncState currentStatus play Oct 11 13:59:37 living volumio[1291]: info: Received an update from plugin. extracting info from payload Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 13:59:37 living volumio[1291]: info: [1791737977255] [80s80s] getContentOfUrl started with url http://iris-90s90s.loverad.io/flow.json?station=141&count=1 Oct 11 13:59:37 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 13:59:37 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 13:59:37 living volumio[1291]: info: [1791737977261] [80s80s] Pushing the next song state Michael Jackson - Blood On the Dance Floor and getting next track. Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::servicePushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is2-ssl.mzstatic.com/image/thumb/Music114/v4/a3/45/e1/a345e1ff-78a8-d29b-b34f-85da553caddb/source/600x600bb.jpg","name":"Michael Jackson - Blood On the Dance Floor","title":"Blood On the Dance Floor","artist":"90s90s Hits","album":"","streaming":true,"disableUiControls":true,"duration":"235","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Oct 11 13:59:37 living volumio[1291]: verbose: CURRENT POSITION 0 Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::syncState stateService play Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::syncState currentStatus play Oct 11 13:59:37 living volumio[1291]: info: Received an update from plugin. extracting info from payload Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 13:59:37 living volumio[1291]: info: [1791737977279] [80s80s] getContentOfUrl started with url http://iris-90s90s.loverad.io/flow.json?station=141&count=1 Oct 11 13:59:37 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 13:59:37 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 13:59:37 living systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 11 13:59:37 living volumio[1291]: info: [1791737977523] [80s80s] Pushing the next song state Michael Jackson - Blood On the Dance Floor and getting next track. Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::servicePushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is2-ssl.mzstatic.com/image/thumb/Music114/v4/a3/45/e1/a345e1ff-78a8-d29b-b34f-85da553caddb/source/600x600bb.jpg","name":"Michael Jackson - Blood On the Dance Floor","title":"Blood On the Dance Floor","artist":"90s90s Hits","album":"","streaming":true,"disableUiControls":true,"duration":"235","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Oct 11 13:59:37 living volumio[1291]: verbose: CURRENT POSITION 0 Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::syncState stateService play Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::syncState currentStatus play Oct 11 13:59:37 living volumio[1291]: info: Received an update from plugin. extracting info from payload Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 13:59:37 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 13:59:37 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 13:59:37 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 13:59:37 living volumio[1291]: info: [1791737977537] [80s80s] getContentOfUrl started with url http://iris-90s90s.loverad.io/flow.json?station=141&count=1 Oct 11 13:59:37 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 13:59:37 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 13:59:37 living volumio[1291]: info: [1791737977835] [80s80s] received new event containing 1 songs. Oct 11 13:59:37 living volumio[1291]: info: [1791737977835] [80s80s] PlayNextTrack API delay: 30 Oct 11 13:59:37 living volumio[1291]: info: [1791737977836] [80s80s] Setting timer to: 235000 milliseconds. Oct 11 13:59:37 living volumio[1291]: info: [1791737977844] [80s80s] received new event containing 1 songs. Oct 11 13:59:37 living volumio[1291]: info: [1791737977844] [80s80s] PlayNextTrack API delay: 30 Oct 11 13:59:37 living volumio[1291]: info: [1791737977845] [80s80s] Setting timer to: 235000 milliseconds. Oct 11 13:59:38 living volumio[1291]: info: [1791737978012] [80s80s] received new event containing 1 songs. Oct 11 13:59:38 living volumio[1291]: info: [1791737978013] [80s80s] PlayNextTrack API delay: 30 Oct 11 13:59:38 living volumio[1291]: info: [1791737978014] [80s80s] Setting timer to: 235000 milliseconds. Oct 11 13:59:38 living systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 11 13:59:38 living systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 11 14:00:16 living go-librespot[23437]: time="2026-10-11T14:00:16-03:00" level=debug msg="obtained new client token: AAGjdXVsACacnJWYImT4Z1nHuw3MiHTKNoZSN3dWnbv9qs0yQA0KWEnbk1vJ793bgT9ZnHkV8Y3KLo6NkhPdaVIa221JZaioWLGYGE1X7c6IytG2kl3Kg/VrOle75PkbBJqK42r9hsn6GDXKppDt/StckLNdWINz/5OlhKHQAzj4V8vEV+ogNmij8BBdVmpF/HBNIfhOb9Bim0lHJlu+Qv4e7IjXw8y7dy5VpvVCKCPCPDjAsnT8tuRXj8g=" Oct 11 14:00:16 living go-librespot[23437]: time="2026-10-11T14:00:16-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 11 14:00:16 living go-librespot[23437]: time="2026-10-11T14:00:16-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Oct 11 14:00:17 living go-librespot[23437]: time="2026-10-11T14:00:17-03:00" level=debug msg="completed keyexchange" Oct 11 14:00:17 living go-librespot[23437]: time="2026-10-11T14:00:17-03:00" level=debug msg="completed challenge" Oct 11 14:00:17 living go-librespot[23437]: time="2026-10-11T14:00:17-03:00" level=info msg="authenticated AP" username="co*****77" Oct 11 14:00:17 living go-librespot[23437]: time="2026-10-11T14:00:17-03:00" level=info msg="authenticated Login5" username="co*****77" Oct 11 14:00:17 living go-librespot[23437]: time="2026-10-11T14:00:17-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 11 14:00:17 living go-librespot[23437]: time="2026-10-11T14:00:17-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 11 14:00:17 living go-librespot[23437]: time="2026-10-11T14:00:17-03:00" level=info msg="accepted zeroconf from iPhone" username="co*****77" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="dealer connection opened" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=trace msg="starting accesspoint recv loop" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=trace msg="starting dealer recv loop" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=trace msg="received accesspoint ping" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="received connection id: NzRkMDc2NTEtNTli...RkZFQkRCMTFDRQ==" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=trace msg="received accesspoint pong ack" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="put connect state because NEW_DEVICE" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="handling transfer player command from d02d5f62f51ad8b8d1d32e495ef0f177a5852c81" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="resolved context of track" uri="spotify:playlist:195r1L5buIxeNFk5JrHWn1" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=trace msg="fetched new page 0 with 47 items (list: 47)" uri="spotify:playlist:195r1L5buIxeNFk5JrHWn1" Oct 11 14:00:18 living go-librespot[23437]: time="2026-10-11T14:00:18-03:00" level=debug msg="loading track (paused: true, position: 1045ms)" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:19 living go-librespot[23437]: time="2026-10-11T14:00:19-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 14:00:19 living go-librespot[23437]: time="2026-10-11T14:00:19-03:00" level=trace msg="emitting websocket event: will_play" Oct 11 14:00:19 living go-librespot[23437]: time="2026-10-11T14:00:19-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 438" Oct 11 14:00:19 living volumio[1291]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:195r1L5buIxeNFk5JrHWn1","uri":"spotify:track:5lQPzm2oknUgFEho5QEBeh","play_origin":"playlist/ondemand"}} Oct 11 14:00:19 living go-librespot[23437]: time="2026-10-11T14:00:19-03:00" level=debug msg="selected format OGG_VORBIS_320 (ff80ca1f471714bf1c96a9f044e1a3268cfbd88d)" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:19 living go-librespot[23437]: time="2026-10-11T14:00:19-03:00" level=debug msg="requested aes key for file ff80ca1f471714bf1c96a9f044e1a3268cfbd88d, gid: 5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:19 living go-librespot[23437]: time="2026-10-11T14:00:19-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="fetched first chunk of 24, total size is 12164324 bytes" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=trace msg="seek to 1045ms (diff: 368ms, samples: 46084, bytes: 18584)" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="created new output device" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=info msg="loaded track \"Garota de ipanema\" (paused: true, position: 1045ms, duration: 276133ms, prefetched: false)" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:20 living volumio[1291]: info: [1791738020114] [80s80s] Pushing the next song state Michael Jackson - Blood On the Dance Floor and getting next track. Oct 11 14:00:20 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 14:00:20 living volumio[1291]: info: CoreCommandRouter::servicePushState Oct 11 14:00:20 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 14:00:20 living volumio[1291]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is2-ssl.mzstatic.com/image/thumb/Music114/v4/a3/45/e1/a345e1ff-78a8-d29b-b34f-85da553caddb/source/600x600bb.jpg","name":"Michael Jackson - Blood On the Dance Floor","title":"Blood On the Dance Floor","artist":"90s90s Hits","album":"","streaming":true,"disableUiControls":true,"duration":"235","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Oct 11 14:00:20 living volumio[1291]: verbose: CURRENT POSITION 0 Oct 11 14:00:20 living volumio[1291]: info: CoreStateMachine::syncState stateService play Oct 11 14:00:20 living volumio[1291]: info: CoreStateMachine::syncState currentStatus play Oct 11 14:00:20 living volumio[1291]: info: Received an update from plugin. extracting info from payload Oct 11 14:00:20 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 14:00:20 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 14:00:20 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 14:00:20 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 14:00:20 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 14:00:20 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 14:00:20 living volumio[1291]: info: [1791738020126] [80s80s] getContentOfUrl started with url http://iris-90s90s.loverad.io/flow.json?station=141&count=1 Oct 11 14:00:20 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 14:00:20 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=trace msg="emitting websocket event: metadata" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=trace msg="emitting websocket event: active" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="sending successful reply for dealer request" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 11 14:00:20 living volumio[1291]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5lQPzm2oknUgFEho5QEBeh","name":"Garota de ipanema","artist_names":["Caçulinha"],"album_name":"VIP Collection: Bossa Nova","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02d7a3dc00fbfc85dd411bea2a","position":1045,"duration":276133,"release_date":"year:2009","track_number":5,"disc_number":1}} Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:20 living volumio[1291]: SPOTIFY: received: {"type":"active","data":null} Oct 11 14:00:20 living volumio[1291]: info: Aligning Spotify Volume to Volumio Volume Oct 11 14:00:20 living volumio[1291]: info: CoreCommandRouter::volumioGetState Oct 11 14:00:20 living volumio[1291]: info: CorePlayQueue::getTrack 0 Oct 11 14:00:20 living volumio[1291]: info: Setting Spotify Volume from Volumio: 100 Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 14:00:20 living go-librespot[23437]: time="2026-10-11T14:00:20-03:00" level=trace msg="emitting websocket event: paused" Oct 11 14:00:20 living volumio[1291]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:195r1L5buIxeNFk5JrHWn1","uri":"spotify:track:5lQPzm2oknUgFEho5QEBeh","play_origin":"playlist/ondemand"}} Oct 11 14:00:20 living volumio[1291]: info: Spotify is playing in volatile mode Oct 11 14:00:20 living volumio[1291]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 14:00:20 living volumio[1291]: SPOTIFY: UNSET VOLATILE Oct 11 14:00:20 living volumio[1291]: SPOTIFY: {"status":"play","position":0,"title":"Michael Jackson - Blood On the Dance Floor","artist":"90s90s Hits","album":"","albumart":"https://is2-ssl.mzstatic.com/image/thumb/Music114/v4/a3/45/e1/a345e1ff-78a8-d29b-b34f-85da553caddb/source/600x600bb.jpg","uri":"http://streams.90s90s.de/pop/mp3-192/volumio","trackType":"80s80s Radio","seek":0,"duration":"235","samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} Oct 11 14:00:20 living volumio[1291]: info: Setting Spotify stop after unset volatile call Oct 11 14:00:20 living volumio[1291]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 14:00:20 living volumio[1291]: SPOTIFY: {"status":"pause","service":"spop","title":"Garota de ipanema","artist":"Caçulinha","album":"VIP Collection: Bossa Nova","albumart":"https://i.scdn.co/image/ab67616d00001e02d7a3dc00fbfc85dd411bea2a","uri":"spotify:track:5lQPzm2oknUgFEho5QEBeh","trackType":"spotify","seek":1045,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 14:00:20 living volumio[1291]: info: CoreCommandRouter::servicePushState Oct 11 14:00:20 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 14:00:20 living volumio[1291]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 14:00:20 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 14:00:20 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 14:00:20 living volumio[1291]: info: touch_display: Setting screensaver timeout to 120 seconds. Oct 11 14:00:21 living volumio[1291]: info: Spotify Stop Oct 11 14:00:21 living volumio[1291]: SPOTIFY: SPOTIFY STOP Oct 11 14:00:21 living volumio[1291]: SPOTIFY: {"status":"pause","title":"Garota de ipanema","artist":"Caçulinha","album":"VIP Collection: Bossa Nova","albumart":"https://i.scdn.co/image/ab67616d00001e02d7a3dc00fbfc85dd411bea2a","uri":"spotify:track:5lQPzm2oknUgFEho5QEBeh","trackType":"spotify","codec":"ogg","seek":1045,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Oct 11 14:00:21 living volumio[1291]: info: [1791738021282] [80s80s] received new event containing 1 songs. Oct 11 14:00:21 living volumio[1291]: info: [1791738021282] [80s80s] PlayNextTrack API delay: 30 Oct 11 14:00:21 living volumio[1291]: info: [1791738021283] [80s80s] Setting timer to: 235000 milliseconds. Oct 11 14:00:21 living volumio[1291]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Oct 11 14:00:21 living volumio[1291]: info: Sending Spotify command with payload to local API: /player/volume Oct 11 14:00:21 living go-librespot[23437]: time="2026-10-11T14:00:21-03:00" level=debug msg="update volume requested to 65535/65535" Oct 11 14:00:22 living go-librespot[23437]: time="2026-10-11T14:00:22-03:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 11 14:00:22 living go-librespot[23437]: time="2026-10-11T14:00:22-03:00" level=trace msg="emitting websocket event: volume" Oct 11 14:00:22 living volumio[1291]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Oct 11 14:00:22 living volumio[1291]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=debug msg="handling resume player command from d02d5f62f51ad8b8d1d32e495ef0f177a5852c81" Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=trace msg="seek to 1045ms (diff: 368ms, samples: 46084, bytes: 18584)" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=debug msg="resume track at 675ms" Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=trace msg="scheduling prefetch in 245s" Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=debug msg="sending successful reply for dealer request" Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 14:00:28 living go-librespot[23437]: time="2026-10-11T14:00:28-03:00" level=trace msg="emitting websocket event: playing" Oct 11 14:00:28 living volumio[1291]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:195r1L5buIxeNFk5JrHWn1","uri":"spotify:track:5lQPzm2oknUgFEho5QEBeh","resume":true,"play_origin":"playlist/ondemand"}} Oct 11 14:00:28 living volumio[1291]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 14:00:28 living volumio[1291]: SPOTIFY: {"status":"play","service":"spop","title":"Garota de ipanema","artist":"Caçulinha","album":"VIP Collection: Bossa Nova","albumart":"https://i.scdn.co/image/ab67616d00001e02d7a3dc00fbfc85dd411bea2a","uri":"spotify:track:5lQPzm2oknUgFEho5QEBeh","trackType":"spotify","seek":1045,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 11 14:00:28 living volumio[1291]: info: CoreCommandRouter::servicePushState Oct 11 14:00:28 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 14:00:28 living volumio[1291]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 14:00:28 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 14:00:28 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 14:00:29 living go-librespot[23437]: time="2026-10-11T14:00:29-03:00" level=debug msg="handling update_context player command from d02d5f62f51ad8b8d1d32e495ef0f177a5852c81" Oct 11 14:00:29 living volumio[1291]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 14:00:29 living volumio[1291]: SPOTIFY: {"status":"play","service":"spop","title":"Garota de ipanema","artist":"Caçulinha","album":"VIP Collection: Bossa Nova","albumart":"https://i.scdn.co/image/ab67616d00001e02d7a3dc00fbfc85dd411bea2a","uri":"spotify:track:5lQPzm2oknUgFEho5QEBeh","trackType":"spotify","seek":1045,"duration":276,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 11 14:00:29 living volumio[1291]: info: CoreCommandRouter::servicePushState Oct 11 14:00:29 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 14:00:29 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 14:00:29 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 11 14:00:29 living go-librespot[23437]: time="2026-10-11T14:00:29-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 14:00:29 living go-librespot[23437]: time="2026-10-11T14:00:29-03:00" level=debug msg="sending successful reply for dealer request" Oct 11 14:00:35 living go-librespot[23437]: time="2026-10-11T14:00:35-03:00" level=debug msg="update volume requested to 64879/65535" Oct 11 14:00:35 living go-librespot[23437]: time="2026-10-11T14:00:35-03:00" level=debug msg="update volume requested to 44563/65535" Oct 11 14:00:36 living go-librespot[23437]: time="2026-10-11T14:00:36-03:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 11 14:00:36 living go-librespot[23437]: time="2026-10-11T14:00:36-03:00" level=trace msg="emitting websocket event: volume" Oct 11 14:00:36 living volumio[1291]: SPOTIFY: received: {"type":"volume","data":{"value":68,"max":100}} Oct 11 14:00:36 living volumio[1291]: SPOTIFY: RECEIVED SPOTIFY VOLUME 68 Oct 11 14:00:36 living volumio[1291]: info: Setting Volumio Volume from Spotify: 68 Oct 11 14:00:36 living volumio[1291]: info: VolumeController::SetAlsaVolume68 Oct 11 14:00:36 living volumio[1291]: info: CoreStateMachine::pushState Oct 11 14:00:36 living volumio[1291]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 14:00:36 living volumio[1291]: info: CoreCommandRouter::volumioPushState Oct 11 14:00:36 living volumio[1291]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68 Oct 11 14:00:39 living go-librespot[23437]: time="2026-10-11T14:00:39-03:00" level=debug msg="fetched chunk 4/23, size: 524288" uri="spotify:track:5lQPzm2oknUgFEho5QEBeh" Oct 11 14:00:46 living volumio[1291]: info: [1791738046814] [80s80s] Pushing the next song state Michael Jackson - Blood On the Dance Floor and getting next track. Oct 11 14:00:46 living volumio[1291]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 11 14:00:47 living volumio[1291]: TypeError: Cannot set properties of undefined (setting 'name') Oct 11 14:00:47 living volumio[1291]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Oct 11 14:00:47 living volumio[1291]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Oct 11 14:00:47 living volumio[1291]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Oct 11 14:00:47 living volumio[1291]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Oct 11 14:00:47 living volumio[1291]: at process.processImmediate (node:internal/timers:478:21) Oct 11 14:00:47 living volumio[1291]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 11 14:00:48 living go-librespot[23437]: time="2026-10-11T14:00:48-03:00" level=trace msg="sent dealer ping" Oct 11 14:00:48 living go-librespot[23437]: time="2026-10-11T14:00:48-03:00" level=trace msg="received dealer pong" Oct 11 14:00:49 living sudo[29599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-11 13:59' Oct 11 14:00:49 living sudo[29599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"