May 27 14:50:02 volumio volumio[1788]: info: CoreCommandRouter::volumioGetState May 27 14:50:02 volumio volumio[1788]: info: CorePlayQueue::getTrack 0 May 27 14:50:06 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 27 14:50:06 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 27 14:50:09 volumio go-librespot[2019]: time="2025-05-27T14:50:09+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" May 27 14:50:09 volumio volumio[1788]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify May 27 14:50:09 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 27 14:50:09 volumio volumio[1788]: Cannot find translation for source YouTube2 May 27 14:50:09 volumio volumio[1788]: info: Disabling plugin spop May 27 14:50:09 volumio volumio[1788]: info: Done. May 27 14:50:09 volumio sudo[6707]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service May 27 14:50:09 volumio sudo[6707]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 14:50:09 volumio volumio[1788]: info: Connection to go-librespot Websocket closed May 27 14:50:09 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 27 14:50:09 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 27 14:50:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 27 14:50:09 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:50:09 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:50:09 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:50:09 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:50:09 volumio sudo[6707]: pam_unix(sudo:session): session closed for user root May 27 14:50:11 volumio volumio[1788]: info: Enabling plugin spop May 27 14:50:11 volumio volumio[1788]: info: Loading plugin "spop"... May 27 14:50:11 volumio volumio[1788]: info: PLUGIN START: spop May 27 14:50:11 volumio volumio[1788]: info: Creating Spotify config file May 27 14:50:11 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 14:50:11 volumio volumio[1788]: info: Done. May 27 14:50:11 volumio volumio[1788]: info: Spotify config file written May 27 14:50:11 volumio volumio[1788]: info: No need to fix Spotify hosts May 27 14:50:11 volumio sudo[6724]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 27 14:50:11 volumio sudo[6724]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 14:50:11 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:50:11 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:50:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 27 14:50:11 volumio sudo[6724]: pam_unix(sudo:session): session closed for user root May 27 14:50:11 volumio go-librespot[6726]: go-librespot daemon starting... May 27 14:50:11 volumio go-librespot[6727]: time="2025-05-27T14:50:11+02:00" level=info msg="running go-librespot 0.2.0" May 27 14:50:11 volumio go-librespot[6727]: time="2025-05-27T14:50:11+02:00" level=debug msg="app state loaded" May 27 14:50:11 volumio go-librespot[6727]: time="2025-05-27T14:50:11+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 27 14:50:11 volumio volumio[1788]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 27 14:50:11 volumio volumio[1788]: SPOTIFY: BQDEoZsdETdjr-tMTaT5a5DDR0RmxquRXg883yoGNiKLYAbugxhx_-w74242xu9yC5DBA2mJSlG3gjsL-dvFrdtPaXGUp7J3nDsEeNhDNgSUuYCPluG_6qXkc2HI0PZtQuRt_6_dEWyDR9DZSoL0BU3tPX6EAlA_t3pwfsyhyLOG6LlTRvLTthRhrgfYCGn7Lamg3corrvojmlNz4zeNDVY2bKbxmN7J1Wh_iG48p9v5aw2lnMhJqan3aJ_CSkBiksr40v2LYSv0zFJiocvihgo May 27 14:50:11 volumio volumio[1788]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 27 14:50:11 volumio volumio[1788]: info: New Spotify access token = BQDEoZsdETdjr-tMTaT5a5DDR0RmxquRXg883yoGNiKLYAbugxhx_-w74242xu9yC5DBA2mJSlG3gjsL-dvFrdtPaXGUp7J3nDsEeNhDNgSUuYCPluG_6qXkc2HI0PZtQuRt_6_dEWyDR9DZSoL0BU3tPX6EAlA_t3pwfsyhyLOG6LlTRvLTthRhrgfYCGn7Lamg3corrvojmlNz4zeNDVY2bKbxmN7J1Wh_iG48p9v5aw2lnMhJqan3aJ_CSkBiksr40v2LYSv0zFJiocvihgo May 27 14:50:11 volumio volumio[1788]: info: Spotify credentials grant success - running version from March 24, 2019 May 27 14:50:11 volumio volumio[1788]: SPOTIFY: User informations: {"country":"IT","display_name":"davidef747","email":"davidefilidei@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/davidef747"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/davidef747","id":"davidef747","images":[],"product":"free","type":"user","uri":"spotify:user:davidef747"} May 27 14:50:11 volumio volumio[1788]: info: Spotify Successfully logged in May 27 14:50:11 volumio volumio[1788]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 27 14:50:11 volumio volumio[1788]: info: [1748350211580] CoreMusicLibrary::Adding element Spotify May 27 14:50:11 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 27 14:50:11 volumio volumio[1788]: Cannot find translation for source YouTube2 May 27 14:50:11 volumio volumio[1788]: Cannot find translation for source Spotify May 27 14:50:12 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. May 27 14:50:13 volumio volumio[1788]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 14:50:14 volumio volumio[1788]: info: go-librespot daemon successfully initialized May 27 14:50:16 volumio go-librespot[6727]: time="2025-05-27T14:50:16+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 27 14:50:16 volumio go-librespot[6727]: time="2025-05-27T14:50:16+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 27 14:50:16 volumio go-librespot[6727]: time="2025-05-27T14:50:16+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 27 14:50:16 volumio go-librespot[6727]: time="2025-05-27T14:50:16+02:00" level=info msg="zeroconf server listening on port 39689" May 27 14:50:17 volumio volumio[1788]: info: Initializing connection to go-librespot Websocket May 27 14:50:17 volumio go-librespot[6727]: time="2025-05-27T14:50:17+02:00" level=debug msg="new websocket client" May 27 14:50:17 volumio volumio[1788]: info: Connection to go-librespot Websocket established May 27 14:50:20 volumio volumio[1788]: info: Getting Spotify volume May 27 14:50:20 volumio volumio[1788]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 May 27 14:50:20 volumio volumio[1788]: info: CoreCommandRouter::volumioGetState May 27 14:50:20 volumio volumio[1788]: info: CorePlayQueue::getTrack 0 May 27 14:50:21 volumio go-librespot[6727]: time="2025-05-27T14:50:21+02:00" level=debug msg="obtained new client token: AAAOTBp/vKChWt5kuUx9wyTlN0nvTgwV3DyQNb6nPIgz+cwx9EbcRFxnKAe6cxNVeOuEyDvitv2NeISTJUGOLnbafJzqefsQ0hG/hJOwieakD9jNfeLTGUjklZLvxga+xpAk5NGWp1PwpY4stBnFRhuELzhFlHiwV5QiOOwp8PAbXYdFUIl2XsvCvgBpVROwiMFPSk8NGNTu4U2gMlh9S9/v5EudKKrrwnZcQFdfXISB769/jL0mA179Fw==" May 27 14:50:26 volumio go-librespot[6727]: time="2025-05-27T14:50:26+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 27 14:50:26 volumio go-librespot[6727]: time="2025-05-27T14:50:26+02:00" level=debug msg="completed keyexchange" May 27 14:50:26 volumio go-librespot[6727]: time="2025-05-27T14:50:26+02:00" level=debug msg="completed challenge" May 27 14:50:26 volumio go-librespot[6727]: time="2025-05-27T14:50:26+02:00" level=info msg="authenticated AP as davidef747" May 27 14:50:31 volumio volumio[1788]: info: CoreCommandRouter::volumioGetState May 27 14:50:31 volumio volumio[1788]: info: CorePlayQueue::getTrack 0 May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=info msg="authenticated Login5 as davidef747" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=debug msg="initializing zeroconf session, username: davidef747" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=debug msg="dealer connection opened" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=trace msg="starting accesspoint recv loop" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=trace msg="starting dealer recv loop" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=trace msg="received accesspoint ping" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 27 14:50:31 volumio volumio[1788]: info: Spotify volume: 100 May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=debug msg="received connection id: ZWQ5ZmIxM2MtZDIyNi00NWNkLTk2YTUtOTk5NmUxMmQ4YTk3K2RlYWxlcit0Y3A6Ly8wYWNhNWE2NC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNEZCNjY5OUQwMzg5QkJCQzNCRjE5OUY3OUIzNzkyMzEzNDFGRDE5RTU4ODg4NzQ1MUNFNEE1OThCNUUxMzg0RA==" May 27 14:50:31 volumio go-librespot[6727]: time="2025-05-27T14:50:31+02:00" level=trace msg="received accesspoint pong ack" May 27 14:50:32 volumio go-librespot[6727]: time="2025-05-27T14:50:32+02:00" level=debug msg="put connect state because NEW_DEVICE" May 27 14:50:32 volumio go-librespot[6727]: time="2025-05-27T14:50:32+02:00" level=debug msg="update volume to 65535/65535" May 27 14:50:33 volumio go-librespot[6727]: time="2025-05-27T14:50:33+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 27 14:50:33 volumio go-librespot[6727]: time="2025-05-27T14:50:33+02:00" level=trace msg="emitting websocket event: volume" May 27 14:50:33 volumio volumio[1788]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} May 27 14:50:33 volumio volumio[1788]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 May 27 14:50:35 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 27 14:50:35 volumio volumio[1788]: info: In handleBrowseUri, curUri=spotify May 27 14:50:35 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:35 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:35 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:35 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:38 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 27 14:50:38 volumio volumio[1788]: info: In handleBrowseUri, curUri=spotify:playlist:37i9dQZF1DX6wfQutivYYr May 27 14:50:39 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2QtnkkxwmsGm84fPAx8uTP May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:5bhYjElbPmm2FyB0PxP8Wd May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:6xOEgzkMSZJKz6qtCJsQL5 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:0Pq53cPG2DSuPXABoZrYes May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:1oHT9T42XDgyL2cOWEkfXu May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:0jkAr7eZsvWDLYiQCfaxak May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:6nQFX6iV1hy2gZDroZbFTF May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:1gIahX2xZu1ir2qLmALtUc May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:4GkgNC3bpLqXyuxWvlNfKI May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:7vc09IDmFH0MfyPYHPEWRM May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:1tse93p9ApWJtMGYRxCKNm May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:0ZmhDgy5eWjdLOQFEEe3bm May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2hOVaWpnPpTdqvaRTvI9L5 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2SvLptBWezeSPSpfhL4XC7 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:1ih8OCS4EmDtSL3Do0tWIp May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:311m4sWQq8MZZROimkSGF7 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:6qqrTXSdwiJaq8SO0X2lSe May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2DkiFEQ1ihXcYKaIRsfGFp May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:4Q7d5kMY5ctGgHp8diJ9Rw May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2BptnzpcLO9NAdNdKh2rZy May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2C46EwfXY2ijlt7BfBY5mi May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:4DnrAI8WyUY6gkOwl8GlPN May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:25mDnFOFyPmebNAok8mavk May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:5tOBPD3zL9kWpeELqkzwJC May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:6vbU5lktjuswHhG8ToyljZ May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2WiYCsnOxE29r8Y8gV9aVA May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:6xZCDUaY4XzlhCSHKSW7rf May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:5MJc4IVIt17xEt6angtZcq May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:00URgxWgyVoybGLhhmKr7g May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:3fMv8yD3CR4KuOEddovifJ May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:5TFD2bmFKGhoCRbX61nXY5 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:5M8Z823Sb2BhMpecHksN0T May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:1musbempyJAw5gfSKZHXP9 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:25VdEndwyUDs0DbpfCMfKD May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:6cGhVnQAJRxGVsltCU06vF May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2PhXWpXhWg61SdUO44FIUk May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:7i0zYckMTyvLyKAFxfOKIS May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:3sK8wGT43QFpWrvNQsrQya May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:3FrbT8aqk9xHtTfQc9Z3IR May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:5ITV0zqzjOYfFWpW0xBmRa May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:0GRc3eGTg8HBdWLRGYgqIc May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2z9FUHRkbkV4BObNzbHsFU May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:5niBKNtMNJTSPLTCBTc3wr May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:0rufYF3Mr0ZqdmhrZeAIz6 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:4RTMLSmkfK9kqKlmTPGRzo May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:177cKZBT80QEPlrSS4nLw9 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:4X4R6qsIicxIQIFbnDcJLO May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:0h3w9Sr1gToqxA9gIs5O39 May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:2ALrq527Q49iISVve4PEkn May 27 14:50:39 volumio volumio[1788]: info: Preloading song: spotify:track:5ZLUm9eab8y3tqQ1OhQSHI May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:2QtnkkxwmsGm84fPAx8uTP in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2QtnkkxwmsGm84fPAx8uTP May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:5bhYjElbPmm2FyB0PxP8Wd in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:5bhYjElbPmm2FyB0PxP8Wd May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:6xOEgzkMSZJKz6qtCJsQL5 in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:6xOEgzkMSZJKz6qtCJsQL5 May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2QtnkkxwmsGm84fPAx8uTP","service":"spop","name":"a me mi piace (feat. Manu Chao)","artist":"Alfa","album":"a me mi piace (feat. Manu Chao)","type":"song","duration":140,"albumart":"https://i.scdn.co/image/ab67616d0000b27395966472ed2c18fb1b7779bf","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:0Pq53cPG2DSuPXABoZrYes in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:0Pq53cPG2DSuPXABoZrYes May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:1oHT9T42XDgyL2cOWEkfXu in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:1oHT9T42XDgyL2cOWEkfXu May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5bhYjElbPmm2FyB0PxP8Wd","service":"spop","name":"Nessuna","artist":"Luchè","album":"Il mio lato peggiore","type":"song","duration":223,"albumart":"https://i.scdn.co/image/ab67616d0000b2730bd9d318d1c6c274f1de4177","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:0jkAr7eZsvWDLYiQCfaxak in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:0jkAr7eZsvWDLYiQCfaxak May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:6nQFX6iV1hy2gZDroZbFTF in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:6nQFX6iV1hy2gZDroZbFTF May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:1gIahX2xZu1ir2qLmALtUc in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:1gIahX2xZu1ir2qLmALtUc May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6xOEgzkMSZJKz6qtCJsQL5","service":"spop","name":"La Plena - W Sound 05","artist":"W Sound","album":"La Plena (W Sound 05)","type":"song","duration":150,"albumart":"https://i.scdn.co/image/ab67616d0000b273d629a6041cde59d7ba67143c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:4GkgNC3bpLqXyuxWvlNfKI in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:4GkgNC3bpLqXyuxWvlNfKI May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:7vc09IDmFH0MfyPYHPEWRM in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:7vc09IDmFH0MfyPYHPEWRM May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:1tse93p9ApWJtMGYRxCKNm in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:1tse93p9ApWJtMGYRxCKNm May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0Pq53cPG2DSuPXABoZrYes","service":"spop","name":"Piangere a 90","artist":"BLANCO","album":"Piangere a 90","type":"song","duration":155,"albumart":"https://i.scdn.co/image/ab67616d0000b273f526cde830c67ecf4580b9e2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1oHT9T42XDgyL2cOWEkfXu","service":"spop","name":"Mi Ami Mi Odi","artist":"Elodie","album":"Mi Ami Mi Odi","type":"song","duration":211,"albumart":"https://i.scdn.co/image/ab67616d0000b2732bb330c3efb16aff45d97cf6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:0ZmhDgy5eWjdLOQFEEe3bm in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:0ZmhDgy5eWjdLOQFEEe3bm May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0jkAr7eZsvWDLYiQCfaxak","service":"spop","name":"NEON","artist":"Sfera Ebbasta","album":"SANTANA MONEY GANG","type":"song","duration":226,"albumart":"https://i.scdn.co/image/ab67616d0000b273d6cdd0e09df54245b00fa9c6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1gIahX2xZu1ir2qLmALtUc","service":"spop","name":"Maschio","artist":"Annalisa","album":"Maschio","type":"song","duration":204,"albumart":"https://i.scdn.co/image/ab67616d0000b273c3df97a45e69713d39662170","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:39 volumio volumio[1788]: info: Exploding uri spotify:track:2hOVaWpnPpTdqvaRTvI9L5 in service spop May 27 14:50:39 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2hOVaWpnPpTdqvaRTvI9L5 May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6nQFX6iV1hy2gZDroZbFTF","service":"spop","name":"Bottiglie Vuote (feat. Max Pezzali)","artist":"Pinguini Tattici Nucleari","album":"Bottiglie Vuote (feat. Max Pezzali)","type":"song","duration":194,"albumart":"https://i.scdn.co/image/ab67616d0000b2739645c8d3ee5c7b0e4c1fefb5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:39 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4GkgNC3bpLqXyuxWvlNfKI","service":"spop","name":"Oh Mamma Mia (feat. Rose Villain)","artist":"Guè","album":"Tropico Del Capricorno","type":"song","duration":168,"albumart":"https://i.scdn.co/image/ab67616d0000b273542c034964ebe1acfeecf90e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:2SvLptBWezeSPSpfhL4XC7 in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2SvLptBWezeSPSpfhL4XC7 May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7vc09IDmFH0MfyPYHPEWRM","service":"spop","name":"AMOR","artist":"Achille Lauro","album":"Comuni Mortali","type":"song","duration":177,"albumart":"https://i.scdn.co/image/ab67616d0000b273b4fab6ed24d80b29f21dd36e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1tse93p9ApWJtMGYRxCKNm","service":"spop","name":"Ora che non ho più te","artist":"Cesare Cremonini","album":"Ora che non ho più te","type":"song","duration":303,"albumart":"https://i.scdn.co/image/ab67616d0000b273a9b9eff7f4b27ea38df7bed9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:1ih8OCS4EmDtSL3Do0tWIp in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:1ih8OCS4EmDtSL3Do0tWIp May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0ZmhDgy5eWjdLOQFEEe3bm","service":"spop","name":"Balorda nostalgia","artist":"Olly","album":"Balorda nostalgia","type":"song","duration":197,"albumart":"https://i.scdn.co/image/ab67616d0000b27313d952d57ef460632cc0975f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:311m4sWQq8MZZROimkSGF7 in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:311m4sWQq8MZZROimkSGF7 May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:6qqrTXSdwiJaq8SO0X2lSe in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:6qqrTXSdwiJaq8SO0X2lSe May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2hOVaWpnPpTdqvaRTvI9L5","service":"spop","name":"CHIAMO IO CHIAMI TU","artist":"Gaia","album":"CHIAMO IO CHIAMI TU","type":"song","duration":218,"albumart":"https://i.scdn.co/image/ab67616d0000b273c05f9d4e637f3e788525c470","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:2DkiFEQ1ihXcYKaIRsfGFp in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2DkiFEQ1ihXcYKaIRsfGFp May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:4Q7d5kMY5ctGgHp8diJ9Rw in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:4Q7d5kMY5ctGgHp8diJ9Rw May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2SvLptBWezeSPSpfhL4XC7","service":"spop","name":"SCELTE STUPIDE","artist":"Fedez","album":"SCELTE STUPIDE","type":"song","duration":179,"albumart":"https://i.scdn.co/image/ab67616d0000b273998dd239aae46b4e1ab54f41","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1ih8OCS4EmDtSL3Do0tWIp","service":"spop","name":"BELLA DAVVERO","artist":"Ultimo","album":"BELLA DAVVERO","type":"song","duration":178,"albumart":"https://i.scdn.co/image/ab67616d0000b273ed6acb219a4cfde1a7d8638b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:2BptnzpcLO9NAdNdKh2rZy in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2BptnzpcLO9NAdNdKh2rZy May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:311m4sWQq8MZZROimkSGF7","service":"spop","name":"Ginevra (feat. Geolier)","artist":"Luchè","album":"Il mio lato peggiore","type":"song","duration":228,"albumart":"https://i.scdn.co/image/ab67616d0000b2730bd9d318d1c6c274f1de4177","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:2C46EwfXY2ijlt7BfBY5mi in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2C46EwfXY2ijlt7BfBY5mi May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:4DnrAI8WyUY6gkOwl8GlPN in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:4DnrAI8WyUY6gkOwl8GlPN May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6qqrTXSdwiJaq8SO0X2lSe","service":"spop","name":"Ordinary","artist":"Alex Warren","album":"Ordinary","type":"song","duration":186,"albumart":"https://i.scdn.co/image/ab67616d0000b273000bd02e24b42b372007a785","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:25mDnFOFyPmebNAok8mavk in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:25mDnFOFyPmebNAok8mavk May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2DkiFEQ1ihXcYKaIRsfGFp","service":"spop","name":"LEI","artist":"Marracash","album":"È FINITA LA PACE","type":"song","duration":223,"albumart":"https://i.scdn.co/image/ab67616d0000b273210484981a7d3ec04f5958b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:5tOBPD3zL9kWpeELqkzwJC in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:5tOBPD3zL9kWpeELqkzwJC May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4Q7d5kMY5ctGgHp8diJ9Rw","service":"spop","name":"Nonostante Tutto (feat. Elisa)","artist":"Cesare Cremonini","album":"Nonostante Tutto (feat. Elisa)","type":"song","duration":267,"albumart":"https://i.scdn.co/image/ab67616d0000b273e1d5f756591c384087997846","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:6vbU5lktjuswHhG8ToyljZ in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:6vbU5lktjuswHhG8ToyljZ May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2BptnzpcLO9NAdNdKh2rZy","service":"spop","name":"il ritmo delle cose.","artist":"Rkomi","album":"il ritmo delle cose.","type":"song","duration":192,"albumart":"https://i.scdn.co/image/ab67616d0000b2733b5563bdef6aa671d3f8f53c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:2WiYCsnOxE29r8Y8gV9aVA in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2WiYCsnOxE29r8Y8gV9aVA May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:6xZCDUaY4XzlhCSHKSW7rf in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:6xZCDUaY4XzlhCSHKSW7rf May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2C46EwfXY2ijlt7BfBY5mi","service":"spop","name":"fuorilegge","artist":"Rose Villain","album":"fuorilegge","type":"song","duration":221,"albumart":"https://i.scdn.co/image/ab67616d0000b27362c26bcc878998487b606901","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4DnrAI8WyUY6gkOwl8GlPN","service":"spop","name":"capaz (merengueton)","artist":"Alleh","album":"LA CIUDAD","type":"song","duration":173,"albumart":"https://i.scdn.co/image/ab67616d0000b2736abd0fcf50a20ac09a028c92","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:5MJc4IVIt17xEt6angtZcq in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:5MJc4IVIt17xEt6angtZcq May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:25mDnFOFyPmebNAok8mavk","service":"spop","name":"Islanda","artist":"Pinguini Tattici Nucleari","album":"Islanda","type":"song","duration":217,"albumart":"https://i.scdn.co/image/ab67616d0000b273e5bc100f86fea85bf11719aa","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:00URgxWgyVoybGLhhmKr7g in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:00URgxWgyVoybGLhhmKr7g May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5tOBPD3zL9kWpeELqkzwJC","service":"spop","name":"LA CURA PER ME","artist":"Giorgia","album":"LA CURA PER ME","type":"song","duration":215,"albumart":"https://i.scdn.co/image/ab67616d0000b273772fe0171cabfd0a677f6db9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:3fMv8yD3CR4KuOEddovifJ in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:3fMv8yD3CR4KuOEddovifJ May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:5TFD2bmFKGhoCRbX61nXY5 in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:5TFD2bmFKGhoCRbX61nXY5 May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2WiYCsnOxE29r8Y8gV9aVA","service":"spop","name":"Amarcord","artist":"Sarah Toscano","album":"Amarcord","type":"song","duration":183,"albumart":"https://i.scdn.co/image/ab67616d0000b2731321f42252772a243b8e4526","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:5M8Z823Sb2BhMpecHksN0T in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:5M8Z823Sb2BhMpecHksN0T May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6xZCDUaY4XzlhCSHKSW7rf","service":"spop","name":"Next Summer","artist":"Damiano David","album":"Next Summer","type":"song","duration":165,"albumart":"https://i.scdn.co/image/ab67616d0000b27327b99ccbfee751f2a1ed925c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:40 volumio volumio[1788]: info: Exploding uri spotify:track:1musbempyJAw5gfSKZHXP9 in service spop May 27 14:50:40 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:1musbempyJAw5gfSKZHXP9 May 27 14:50:40 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5MJc4IVIt17xEt6angtZcq","service":"spop","name":"BUIO DAVANTI","artist":"Lazza","album":"LOCURA","type":"song","duration":189,"albumart":"https://i.scdn.co/image/ab67616d0000b27390d7f08f5345410e0efff330","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6vbU5lktjuswHhG8ToyljZ","service":"spop","name":"Depresso fortunato","artist":"Olly","album":"Depresso fortunato","type":"song","duration":212,"albumart":"https://i.scdn.co/image/ab67616d0000b2739c7b6f71e29bbf4247654629","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:25VdEndwyUDs0DbpfCMfKD in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:25VdEndwyUDs0DbpfCMfKD May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:00URgxWgyVoybGLhhmKr7g","service":"spop","name":"Tu Me Quieres - Prod. by Higashi x Roberto Ferrante","artist":"Baby Gang","album":"Tu Me Quieres","type":"song","duration":214,"albumart":"https://i.scdn.co/image/ab67616d0000b27368e6fd0de7257e4070e6851c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:6cGhVnQAJRxGVsltCU06vF in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:6cGhVnQAJRxGVsltCU06vF May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3fMv8yD3CR4KuOEddovifJ","service":"spop","name":"ON FIRE","artist":"Salmo","album":"RANCH","type":"song","duration":201,"albumart":"https://i.scdn.co/image/ab67616d0000b273c7f1389fbcfcae75b180e8b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:2PhXWpXhWg61SdUO44FIUk in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2PhXWpXhWg61SdUO44FIUk May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5TFD2bmFKGhoCRbX61nXY5","service":"spop","name":"NUEVAYoL","artist":"Bad Bunny","album":"DeBÍ TiRAR MáS FOToS","type":"song","duration":183,"albumart":"https://i.scdn.co/image/ab67616d0000b273bbd45c8d36e0e045ef640411","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5M8Z823Sb2BhMpecHksN0T","service":"spop","name":"ANEMA E CORE","artist":"Serena Brancale","album":"ANEMA E CORE","type":"song","duration":166,"albumart":"https://i.scdn.co/image/ab67616d0000b273b22b3c5cd725d86928fae021","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:7i0zYckMTyvLyKAFxfOKIS in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:7i0zYckMTyvLyKAFxfOKIS May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:25VdEndwyUDs0DbpfCMfKD","service":"spop","name":"Incoscienti Giovani","artist":"Achille Lauro","album":"Incoscienti Giovani","type":"song","duration":204,"albumart":"https://i.scdn.co/image/ab67616d0000b273daf87fd4aa102eba7a8e01c5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1musbempyJAw5gfSKZHXP9","service":"spop","name":"Anxiety","artist":"Doechii","album":"Anxiety","type":"song","duration":249,"albumart":"https://i.scdn.co/image/ab67616d0000b2733de7e97b3e5aa3eaccfc19ec","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:3sK8wGT43QFpWrvNQsrQya in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:3sK8wGT43QFpWrvNQsrQya May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2PhXWpXhWg61SdUO44FIUk","service":"spop","name":"Umore marea","artist":"Bresh","album":"Umore marea","type":"song","duration":158,"albumart":"https://i.scdn.co/image/ab67616d0000b273beb3f9fd9844a63c222205a6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6cGhVnQAJRxGVsltCU06vF","service":"spop","name":"Vibe","artist":"Guè","album":"Tropico Del Capricorno","type":"song","duration":151,"albumart":"https://i.scdn.co/image/ab67616d0000b273542c034964ebe1acfeecf90e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:3FrbT8aqk9xHtTfQc9Z3IR in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:3FrbT8aqk9xHtTfQc9Z3IR May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7i0zYckMTyvLyKAFxfOKIS","service":"spop","name":"SOGNO AMERICANO","artist":"Artie 5ive","album":"LA BELLAVITA","type":"song","duration":176,"albumart":"https://i.scdn.co/image/ab67616d0000b2731964424c80ddd75d0fdc3cff","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:5ITV0zqzjOYfFWpW0xBmRa in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:5ITV0zqzjOYfFWpW0xBmRa May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3sK8wGT43QFpWrvNQsrQya","service":"spop","name":"DtMF","artist":"Bad Bunny","album":"DeBÍ TiRAR MáS FOToS","type":"song","duration":237,"albumart":"https://i.scdn.co/image/ab67616d0000b273bbd45c8d36e0e045ef640411","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:0GRc3eGTg8HBdWLRGYgqIc in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:0GRc3eGTg8HBdWLRGYgqIc May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3FrbT8aqk9xHtTfQc9Z3IR","service":"spop","name":"VVS CARTIER","artist":"Sfera Ebbasta","album":"SANTANA MONEY GANG","type":"song","duration":180,"albumart":"https://i.scdn.co/image/ab67616d0000b273d6cdd0e09df54245b00fa9c6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:2z9FUHRkbkV4BObNzbHsFU in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2z9FUHRkbkV4BObNzbHsFU May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5ITV0zqzjOYfFWpW0xBmRa","service":"spop","name":"Show Me Love","artist":"WizTheMc","album":"Show Me Love","type":"song","duration":176,"albumart":"https://i.scdn.co/image/ab67616d0000b2739263dc4504ccf1b02899d9ae","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:5niBKNtMNJTSPLTCBTc3wr in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:5niBKNtMNJTSPLTCBTc3wr May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0GRc3eGTg8HBdWLRGYgqIc","service":"spop","name":"Azizam","artist":"Ed Sheeran","album":"Azizam","type":"song","duration":162,"albumart":"https://i.scdn.co/image/ab67616d0000b273d29a003b6e8d4c1c47bd4da4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:0rufYF3Mr0ZqdmhrZeAIz6 in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:0rufYF3Mr0ZqdmhrZeAIz6 May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2z9FUHRkbkV4BObNzbHsFU","service":"spop","name":"Born With a Broken Heart","artist":"Damiano David","album":"Born With a Broken Heart","type":"song","duration":208,"albumart":"https://i.scdn.co/image/ab67616d0000b273c105fb55474f224476c23008","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:track:4RTMLSmkfK9kqKlmTPGRzo in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:4RTMLSmkfK9kqKlmTPGRzo May 27 14:50:41 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:41 volumio volumio[1788]: info: CoreCommandRouter::volumioReplaceandPlayItems May 27 14:50:41 volumio volumio[1788]: info: CoreStateMachine::ClearQueue May 27 14:50:41 volumio volumio[1788]: info: CoreStateMachine::stop May 27 14:50:41 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:41 volumio volumio[1788]: info: CorePlayQueue::clearPlayQueue May 27 14:50:41 volumio volumio[1788]: info: CorePlayQueue::saveQueue May 27 14:50:41 volumio volumio[1788]: info: CoreCommandRouter::volumioPushQueue May 27 14:50:41 volumio volumio[1788]: info: CoreStateMachine::addQueueItems May 27 14:50:41 volumio volumio[1788]: info: CorePlayQueue::addQueueItems May 27 14:50:41 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:41 volumio volumio[1788]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1DX6wfQutivYYr May 27 14:50:41 volumio volumio[1788]: info: Exploding uri spotify:user:spotify:playlist:37i9dQZF1DX6wfQutivYYr in service spop May 27 14:50:41 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:user:spotify:playlist:37i9dQZF1DX6wfQutivYYr May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5niBKNtMNJTSPLTCBTc3wr","service":"spop","name":"Un mondo a parte","artist":"Jovanotti","album":"Il corpo umano VOL. 1","type":"song","duration":240,"albumart":"https://i.scdn.co/image/ab67616d0000b273c6ff1eb10bf2303890b098c2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0rufYF3Mr0ZqdmhrZeAIz6","service":"spop","name":"In auto alle 6:00 (feat. Lazza)","artist":"Emis Killa","album":"In auto alle 6:00 (feat. Lazza)","type":"song","duration":167,"albumart":"https://i.scdn.co/image/ab67616d0000b27375bf1558cbac41be8af6caea","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:41 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4RTMLSmkfK9kqKlmTPGRzo","service":"spop","name":"La tana del granchio","artist":"Bresh","album":"La tana del granchio","type":"song","duration":209,"albumart":"https://i.scdn.co/image/ab67616d0000b27363b8ebe611b0e266e15afcab","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:42 volumio volumio[1788]: info: CoreCommandRouter::volumioPushQueue May 27 14:50:42 volumio volumio[1788]: info: CorePlayQueue::saveQueue May 27 14:50:42 volumio volumio[1788]: info: CoreStateMachine::updateTrackBlock May 27 14:50:42 volumio volumio[1788]: info: CorePlayQueue::getTrackBlock May 27 14:50:42 volumio volumio[1788]: info: CoreCommandRouter::volumioPlay May 27 14:50:42 volumio volumio[1788]: info: CoreStateMachine::play index 0 May 27 14:50:42 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:42 volumio volumio[1788]: info: CoreStateMachine::stop May 27 14:50:42 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:42 volumio volumio[1788]: info: CoreStateMachine::play index undefined May 27 14:50:42 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:42 volumio volumio[1788]: info: CorePlayQueue::getTrack 0 May 27 14:50:42 volumio volumio[1788]: info: CoreStateMachine::startPlaybackTimer May 27 14:50:42 volumio volumio[1788]: info: CorePlayQueue::getTrack 0 May 27 14:50:42 volumio volumio[1788]: info: [1748350242170] ControllerSpotify::clearAddPlayTrack May 27 14:50:42 volumio volumio[1788]: info: Sending Spotify command with payload to local API: /player/play May 27 14:50:42 volumio go-librespot[6727]: time="2025-05-27T14:50:42+02:00" level=debug msg="resolved context of track" uri="spotify:track:2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:42 volumio go-librespot[6727]: time="2025-05-27T14:50:42+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:42 volumio go-librespot[6727]: time="2025-05-27T14:50:42+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:42 volumio go-librespot[6727]: time="2025-05-27T14:50:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:50:42 volumio go-librespot[6727]: time="2025-05-27T14:50:42+02:00" level=trace msg="emitting websocket event: will_play" May 27 14:50:42 volumio volumio[1788]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2QtnkkxwmsGm84fPAx8uTP","play_origin":"go-librespot"}} May 27 14:50:42 volumio go-librespot[6727]: time="2025-05-27T14:50:42+02:00" level=debug msg="selected format OGG_VORBIS_320 (ef02db364083fdff905e16c3441300ed874e05a3)" uri="spotify:track:2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:42 volumio go-librespot[6727]: time="2025-05-27T14:50:42+02:00" level=debug msg="requested aes key for file ef02db364083fdff905e16c3441300ed874e05a3, gid: 2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:42 volumio go-librespot[6727]: time="2025-05-27T14:50:42+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2QtnkkxwmsGm84fPAx8uTP: failed retrieving audio key: failed retrieving aes key with code 1" May 27 14:50:42 volumio volumio[1788]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 27 14:50:48 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 27 14:50:48 volumio dbus-daemon[608]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.85' (uid=0 pid=6780 comm="timedatectl show --property=NTPSynchronized --valu") May 27 14:50:48 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 27 14:50:48 volumio dbus-daemon[608]: [system] Successfully activated service 'org.freedesktop.timedate1' May 27 14:50:48 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. May 27 14:50:48 volumio setdatetime-helper.sh[6779]: Time is already synchronized. May 27 14:50:48 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 27 14:50:48 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 27 14:50:55 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:55 volumio volumio[1788]: info: CoreCommandRouter::volumioReplaceandPlayItems May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::ClearQueue May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::stop May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:55 volumio volumio[1788]: info: CorePlayQueue::clearPlayQueue May 27 14:50:55 volumio volumio[1788]: info: CorePlayQueue::saveQueue May 27 14:50:55 volumio volumio[1788]: info: CoreCommandRouter::volumioPushQueue May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::addQueueItems May 27 14:50:55 volumio volumio[1788]: info: CorePlayQueue::addQueueItems May 27 14:50:55 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:55 volumio volumio[1788]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1DX6wfQutivYYr May 27 14:50:55 volumio volumio[1788]: info: Using cached record of: spotify:user:spotify:playlist:37i9dQZF1DX6wfQutivYYr May 27 14:50:55 volumio volumio[1788]: info: CoreCommandRouter::volumioPushQueue May 27 14:50:55 volumio volumio[1788]: info: CorePlayQueue::saveQueue May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::updateTrackBlock May 27 14:50:55 volumio volumio[1788]: info: CorePlayQueue::getTrackBlock May 27 14:50:55 volumio volumio[1788]: info: CoreCommandRouter::volumioPlay May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::play index 0 May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::stop May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::play index undefined May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:55 volumio volumio[1788]: info: CorePlayQueue::getTrack 0 May 27 14:50:55 volumio volumio[1788]: info: CoreStateMachine::startPlaybackTimer May 27 14:50:55 volumio volumio[1788]: info: CorePlayQueue::getTrack 0 May 27 14:50:55 volumio volumio[1788]: info: [1748350255386] ControllerSpotify::clearAddPlayTrack May 27 14:50:55 volumio volumio[1788]: info: Sending Spotify command with payload to local API: /player/play May 27 14:50:55 volumio go-librespot[6727]: time="2025-05-27T14:50:55+02:00" level=debug msg="resolved context of track" uri="spotify:track:2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:55 volumio go-librespot[6727]: time="2025-05-27T14:50:55+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:55 volumio go-librespot[6727]: time="2025-05-27T14:50:55+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:55 volumio go-librespot[6727]: time="2025-05-27T14:50:55+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:50:55 volumio go-librespot[6727]: time="2025-05-27T14:50:55+02:00" level=trace msg="emitting websocket event: will_play" May 27 14:50:55 volumio volumio[1788]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2QtnkkxwmsGm84fPAx8uTP","play_origin":"go-librespot"}} May 27 14:50:55 volumio go-librespot[6727]: time="2025-05-27T14:50:55+02:00" level=debug msg="selected format OGG_VORBIS_320 (ef02db364083fdff905e16c3441300ed874e05a3)" uri="spotify:track:2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:55 volumio go-librespot[6727]: time="2025-05-27T14:50:55+02:00" level=debug msg="requested aes key for file ef02db364083fdff905e16c3441300ed874e05a3, gid: 2QtnkkxwmsGm84fPAx8uTP" May 27 14:50:55 volumio go-librespot[6727]: time="2025-05-27T14:50:55+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2QtnkkxwmsGm84fPAx8uTP: failed retrieving audio key: failed retrieving aes key with code 1" May 27 14:50:55 volumio volumio[1788]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 27 14:50:58 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:58 volumio volumio[1788]: info: CoreCommandRouter::volumioReplaceandPlayItems May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::ClearQueue May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::stop May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:58 volumio volumio[1788]: info: CorePlayQueue::clearPlayQueue May 27 14:50:58 volumio volumio[1788]: info: CorePlayQueue::saveQueue May 27 14:50:58 volumio volumio[1788]: info: CoreCommandRouter::volumioPushQueue May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::addQueueItems May 27 14:50:58 volumio volumio[1788]: info: CorePlayQueue::addQueueItems May 27 14:50:58 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2QtnkkxwmsGm84fPAx8uTP May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2QtnkkxwmsGm84fPAx8uTP May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:5bhYjElbPmm2FyB0PxP8Wd May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:5bhYjElbPmm2FyB0PxP8Wd May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:6xOEgzkMSZJKz6qtCJsQL5 May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:6xOEgzkMSZJKz6qtCJsQL5 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:0Pq53cPG2DSuPXABoZrYes May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:0Pq53cPG2DSuPXABoZrYes May 27 14:50:58 volumio volumio[1788]: info: CoreCommandRouter::volumioPushQueue May 27 14:50:58 volumio volumio[1788]: info: CorePlayQueue::saveQueue May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::updateTrackBlock May 27 14:50:58 volumio volumio[1788]: info: CorePlayQueue::getTrackBlock May 27 14:50:58 volumio volumio[1788]: info: CoreCommandRouter::volumioPlay May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::play index 3 May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::addQueueItems May 27 14:50:58 volumio volumio[1788]: info: CorePlayQueue::addQueueItems May 27 14:50:58 volumio volumio[1788]: info: Preload queue cleared May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:1oHT9T42XDgyL2cOWEkfXu May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:1oHT9T42XDgyL2cOWEkfXu May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:0jkAr7eZsvWDLYiQCfaxak May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:0jkAr7eZsvWDLYiQCfaxak May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:6nQFX6iV1hy2gZDroZbFTF May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:6nQFX6iV1hy2gZDroZbFTF May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:1gIahX2xZu1ir2qLmALtUc May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:1gIahX2xZu1ir2qLmALtUc May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:4GkgNC3bpLqXyuxWvlNfKI May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:4GkgNC3bpLqXyuxWvlNfKI May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:7vc09IDmFH0MfyPYHPEWRM May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:7vc09IDmFH0MfyPYHPEWRM May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:1tse93p9ApWJtMGYRxCKNm May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:1tse93p9ApWJtMGYRxCKNm May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:0ZmhDgy5eWjdLOQFEEe3bm May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:0ZmhDgy5eWjdLOQFEEe3bm May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2hOVaWpnPpTdqvaRTvI9L5 May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2hOVaWpnPpTdqvaRTvI9L5 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2SvLptBWezeSPSpfhL4XC7 May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2SvLptBWezeSPSpfhL4XC7 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:1ih8OCS4EmDtSL3Do0tWIp May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:1ih8OCS4EmDtSL3Do0tWIp May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:311m4sWQq8MZZROimkSGF7 May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:311m4sWQq8MZZROimkSGF7 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:6qqrTXSdwiJaq8SO0X2lSe May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:6qqrTXSdwiJaq8SO0X2lSe May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2DkiFEQ1ihXcYKaIRsfGFp May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2DkiFEQ1ihXcYKaIRsfGFp May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:4Q7d5kMY5ctGgHp8diJ9Rw May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:4Q7d5kMY5ctGgHp8diJ9Rw May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2BptnzpcLO9NAdNdKh2rZy May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2BptnzpcLO9NAdNdKh2rZy May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2C46EwfXY2ijlt7BfBY5mi May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2C46EwfXY2ijlt7BfBY5mi May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:4DnrAI8WyUY6gkOwl8GlPN May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:4DnrAI8WyUY6gkOwl8GlPN May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:25mDnFOFyPmebNAok8mavk May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:25mDnFOFyPmebNAok8mavk May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:5tOBPD3zL9kWpeELqkzwJC May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:5tOBPD3zL9kWpeELqkzwJC May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:6vbU5lktjuswHhG8ToyljZ May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:6vbU5lktjuswHhG8ToyljZ May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2WiYCsnOxE29r8Y8gV9aVA May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2WiYCsnOxE29r8Y8gV9aVA May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:6xZCDUaY4XzlhCSHKSW7rf May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:6xZCDUaY4XzlhCSHKSW7rf May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:5MJc4IVIt17xEt6angtZcq May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:5MJc4IVIt17xEt6angtZcq May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:00URgxWgyVoybGLhhmKr7g May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:00URgxWgyVoybGLhhmKr7g May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:3fMv8yD3CR4KuOEddovifJ May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:3fMv8yD3CR4KuOEddovifJ May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:5TFD2bmFKGhoCRbX61nXY5 May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:5TFD2bmFKGhoCRbX61nXY5 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:5M8Z823Sb2BhMpecHksN0T May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:5M8Z823Sb2BhMpecHksN0T May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:1musbempyJAw5gfSKZHXP9 May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:1musbempyJAw5gfSKZHXP9 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:25VdEndwyUDs0DbpfCMfKD May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:25VdEndwyUDs0DbpfCMfKD May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:6cGhVnQAJRxGVsltCU06vF May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:6cGhVnQAJRxGVsltCU06vF May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2PhXWpXhWg61SdUO44FIUk May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2PhXWpXhWg61SdUO44FIUk May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:7i0zYckMTyvLyKAFxfOKIS May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:7i0zYckMTyvLyKAFxfOKIS May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:3sK8wGT43QFpWrvNQsrQya May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:3sK8wGT43QFpWrvNQsrQya May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:3FrbT8aqk9xHtTfQc9Z3IR May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:3FrbT8aqk9xHtTfQc9Z3IR May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:5ITV0zqzjOYfFWpW0xBmRa May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:5ITV0zqzjOYfFWpW0xBmRa May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:0GRc3eGTg8HBdWLRGYgqIc May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:0GRc3eGTg8HBdWLRGYgqIc May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2z9FUHRkbkV4BObNzbHsFU May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:2z9FUHRkbkV4BObNzbHsFU May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:5niBKNtMNJTSPLTCBTc3wr May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:5niBKNtMNJTSPLTCBTc3wr May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:0rufYF3Mr0ZqdmhrZeAIz6 May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:0rufYF3Mr0ZqdmhrZeAIz6 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:4RTMLSmkfK9kqKlmTPGRzo May 27 14:50:58 volumio volumio[1788]: info: Using cached record of: spotify:track:4RTMLSmkfK9kqKlmTPGRzo May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:177cKZBT80QEPlrSS4nLw9 May 27 14:50:58 volumio volumio[1788]: info: Exploding uri spotify:track:177cKZBT80QEPlrSS4nLw9 in service spop May 27 14:50:58 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:177cKZBT80QEPlrSS4nLw9 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:4X4R6qsIicxIQIFbnDcJLO May 27 14:50:58 volumio volumio[1788]: info: Exploding uri spotify:track:4X4R6qsIicxIQIFbnDcJLO in service spop May 27 14:50:58 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:4X4R6qsIicxIQIFbnDcJLO May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:0h3w9Sr1gToqxA9gIs5O39 May 27 14:50:58 volumio volumio[1788]: info: Exploding uri spotify:track:0h3w9Sr1gToqxA9gIs5O39 in service spop May 27 14:50:58 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:0h3w9Sr1gToqxA9gIs5O39 May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:2ALrq527Q49iISVve4PEkn May 27 14:50:58 volumio volumio[1788]: info: Exploding uri spotify:track:2ALrq527Q49iISVve4PEkn in service spop May 27 14:50:58 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:2ALrq527Q49iISVve4PEkn May 27 14:50:58 volumio volumio[1788]: info: Adding Item to queue: spotify:track:5ZLUm9eab8y3tqQ1OhQSHI May 27 14:50:58 volumio volumio[1788]: info: Exploding uri spotify:track:5ZLUm9eab8y3tqQ1OhQSHI in service spop May 27 14:50:58 volumio volumio[1788]: SPOTIFY: EXPLODING URI:spotify:track:5ZLUm9eab8y3tqQ1OhQSHI May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::stop May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::play index undefined May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:50:58 volumio volumio[1788]: info: CorePlayQueue::getTrack 3 May 27 14:50:58 volumio volumio[1788]: info: CoreStateMachine::startPlaybackTimer May 27 14:50:58 volumio volumio[1788]: info: CorePlayQueue::getTrack 3 May 27 14:50:58 volumio volumio[1788]: info: [1748350258287] ControllerSpotify::clearAddPlayTrack May 27 14:50:58 volumio volumio[1788]: info: Sending Spotify command with payload to local API: /player/play May 27 14:50:58 volumio go-librespot[6727]: time="2025-05-27T14:50:58+02:00" level=debug msg="resolved context of track" uri="spotify:track:0Pq53cPG2DSuPXABoZrYes" May 27 14:50:58 volumio go-librespot[6727]: time="2025-05-27T14:50:58+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0Pq53cPG2DSuPXABoZrYes" May 27 14:50:58 volumio go-librespot[6727]: time="2025-05-27T14:50:58+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0Pq53cPG2DSuPXABoZrYes" May 27 14:50:58 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4X4R6qsIicxIQIFbnDcJLO","service":"spop","name":"Scarabocchi","artist":"Olly","album":"TUTTA VITA","type":"song","duration":180,"albumart":"https://i.scdn.co/image/ab67616d0000b2731e252362775c20ee98f6d3e1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:58 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5ZLUm9eab8y3tqQ1OhQSHI","service":"spop","name":"Abracadabra","artist":"Lady Gaga","album":"Abracadabra","type":"song","duration":223,"albumart":"https://i.scdn.co/image/ab67616d0000b27325304f6dc9dea023ce4b985c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:58 volumio go-librespot[6727]: time="2025-05-27T14:50:58+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:50:58 volumio go-librespot[6727]: time="2025-05-27T14:50:58+02:00" level=trace msg="emitting websocket event: will_play" May 27 14:50:58 volumio volumio[1788]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0Pq53cPG2DSuPXABoZrYes","play_origin":"go-librespot"}} May 27 14:50:58 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0h3w9Sr1gToqxA9gIs5O39","service":"spop","name":"Tutta L'Italia","artist":"Gabry Ponte","album":"Tutta L'Italia","type":"song","duration":176,"albumart":"https://i.scdn.co/image/ab67616d0000b2739e0b57056683cabfa9a35548","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:58 volumio go-librespot[6727]: time="2025-05-27T14:50:58+02:00" level=debug msg="selected format OGG_VORBIS_320 (b34618db3217d42a25c88fa219d37b3b0271f097)" uri="spotify:track:0Pq53cPG2DSuPXABoZrYes" May 27 14:50:58 volumio go-librespot[6727]: time="2025-05-27T14:50:58+02:00" level=debug msg="requested aes key for file b34618db3217d42a25c88fa219d37b3b0271f097, gid: 0Pq53cPG2DSuPXABoZrYes" May 27 14:50:58 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2ALrq527Q49iISVve4PEkn","service":"spop","name":"Nottetempo (feat. Giorgio Poi)","artist":"Franco126","album":"Futuri Possibili","type":"song","duration":175,"albumart":"https://i.scdn.co/image/ab67616d0000b2731ca662be5e898820c3baed34","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:50:58 volumio go-librespot[6727]: time="2025-05-27T14:50:58+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0Pq53cPG2DSuPXABoZrYes: failed retrieving audio key: failed retrieving aes key with code 1" May 27 14:50:58 volumio volumio[1788]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 27 14:51:01 volumio go-librespot[6727]: time="2025-05-27T14:51:01+02:00" level=trace msg="sent dealer ping" May 27 14:51:02 volumio go-librespot[6727]: time="2025-05-27T14:51:02+02:00" level=trace msg="received dealer pong" May 27 14:51:03 volumio volumio[1788]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:177cKZBT80QEPlrSS4nLw9","service":"spop","name":"La Mia Parola (feat. Guè, Joshua, Tormento)","artist":"Shablo","album":"La Mia Parola (feat. Guè, Joshua, Tormento)","type":"song","duration":170,"albumart":"https://i.scdn.co/image/ab67616d0000b2730f708902993b0c688ce57082","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 27 14:51:03 volumio volumio[1788]: info: CoreCommandRouter::volumioPushQueue May 27 14:51:03 volumio volumio[1788]: info: CorePlayQueue::saveQueue May 27 14:51:03 volumio volumio[1788]: info: CoreStateMachine::updateTrackBlock May 27 14:51:03 volumio volumio[1788]: info: CorePlayQueue::getTrackBlock May 27 14:51:10 volumio volumio[1788]: info: CoreCommandRouter::volumioGetState May 27 14:51:10 volumio volumio[1788]: info: CorePlayQueue::getTrack 3 May 27 14:51:15 volumio volumio[1788]: info: CoreCommandRouter::volumioPlay May 27 14:51:15 volumio volumio[1788]: info: CoreStateMachine::play index undefined May 27 14:51:15 volumio volumio[1788]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 14:51:15 volumio volumio[1788]: info: CorePlayQueue::getTrack 3 May 27 14:51:15 volumio volumio[1788]: info: CoreStateMachine::startPlaybackTimer May 27 14:51:15 volumio volumio[1788]: info: CorePlayQueue::getTrack 3 May 27 14:51:15 volumio volumio[1788]: info: [1748350275577] ControllerSpotify::clearAddPlayTrack May 27 14:51:15 volumio volumio[1788]: info: Sending Spotify command with payload to local API: /player/play May 27 14:51:15 volumio go-librespot[6727]: time="2025-05-27T14:51:15+02:00" level=debug msg="resolved context of track" uri="spotify:track:0Pq53cPG2DSuPXABoZrYes" May 27 14:51:15 volumio go-librespot[6727]: time="2025-05-27T14:51:15+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0Pq53cPG2DSuPXABoZrYes" May 27 14:51:15 volumio go-librespot[6727]: time="2025-05-27T14:51:15+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0Pq53cPG2DSuPXABoZrYes" May 27 14:51:15 volumio go-librespot[6727]: time="2025-05-27T14:51:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 27 14:51:15 volumio go-librespot[6727]: time="2025-05-27T14:51:15+02:00" level=trace msg="emitting websocket event: will_play" May 27 14:51:15 volumio volumio[1788]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0Pq53cPG2DSuPXABoZrYes","play_origin":"go-librespot"}} May 27 14:51:15 volumio go-librespot[6727]: time="2025-05-27T14:51:15+02:00" level=debug msg="selected format OGG_VORBIS_320 (b34618db3217d42a25c88fa219d37b3b0271f097)" uri="spotify:track:0Pq53cPG2DSuPXABoZrYes" May 27 14:51:15 volumio go-librespot[6727]: time="2025-05-27T14:51:15+02:00" level=debug msg="requested aes key for file b34618db3217d42a25c88fa219d37b3b0271f097, gid: 0Pq53cPG2DSuPXABoZrYes" May 27 14:51:15 volumio go-librespot[6727]: time="2025-05-27T14:51:15+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0Pq53cPG2DSuPXABoZrYes: failed retrieving audio key: failed retrieving aes key with code 1" May 27 14:51:15 volumio volumio[1788]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 27 14:51:18 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. May 27 14:51:23 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 27 14:51:23 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 27 14:51:26 volumio go-librespot[6727]: time="2025-05-27T14:51:26+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" May 27 14:51:26 volumio volumio[1788]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify May 27 14:51:26 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 27 14:51:26 volumio volumio[1788]: Cannot find translation for source YouTube2 May 27 14:51:26 volumio volumio[1788]: info: Disabling plugin spop May 27 14:51:26 volumio volumio[1788]: info: Done. May 27 14:51:26 volumio volumio[1788]: info: Connection to go-librespot Websocket closed May 27 14:51:26 volumio sudo[6845]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service May 27 14:51:26 volumio sudo[6845]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 14:51:26 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 27 14:51:26 volumio systemd[1]: go-librespot-daemon.service: Killing process 6731 (go-librespot) with signal SIGKILL. May 27 14:51:26 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 27 14:51:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 27 14:51:26 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:51:26 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:51:26 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:51:26 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:51:26 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:51:26 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:51:26 volumio sudo[6845]: pam_unix(sudo:session): session closed for user root May 27 14:51:28 volumio volumio[1788]: info: Enabling plugin spop May 27 14:51:28 volumio volumio[1788]: info: Loading plugin "spop"... May 27 14:51:28 volumio volumio[1788]: info: PLUGIN START: spop May 27 14:51:28 volumio volumio[1788]: info: Creating Spotify config file May 27 14:51:28 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 14:51:28 volumio volumio[1788]: info: Done. May 27 14:51:28 volumio volumio[1788]: info: Spotify config file written May 27 14:51:28 volumio volumio[1788]: info: No need to fix Spotify hosts May 27 14:51:28 volumio sudo[6849]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 27 14:51:28 volumio sudo[6849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 14:51:28 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:51:28 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 27 14:51:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 27 14:51:28 volumio go-librespot[6851]: go-librespot daemon starting... May 27 14:51:28 volumio sudo[6849]: pam_unix(sudo:session): session closed for user root May 27 14:51:28 volumio go-librespot[6852]: time="2025-05-27T14:51:28+02:00" level=info msg="running go-librespot 0.2.0" May 27 14:51:28 volumio go-librespot[6852]: time="2025-05-27T14:51:28+02:00" level=debug msg="app state loaded" May 27 14:51:28 volumio go-librespot[6852]: time="2025-05-27T14:51:28+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 27 14:51:28 volumio volumio[1788]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 27 14:51:28 volumio volumio[1788]: SPOTIFY: BQDVTwdV1Z1MV4jf-PIMDRyzJmV_y0jrxamC9Bge-nPJ6Sjq5etOrFThAH7bGdqhtsdjXlXwiMUeZvFnhEDwLCdRr-p8kbiQZCvBG4mlpbhn8_aBQ5m55Kv6-PdVC0t_EmAoGuAH_b_cW4KH4lc-SkdLg4HGju3AZ7OdUlku4EI91As2ZS0B-loEjdT56ddVNwE4QuGstSqenOZ6j1I2B4EjIlNr-nyUJpHtPJAgcxKusO6vitwpl8iExFujzZ1KtjSR739lSPaGLHG9mY_a5zc May 27 14:51:28 volumio volumio[1788]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 27 14:51:28 volumio volumio[1788]: info: New Spotify access token = BQDVTwdV1Z1MV4jf-PIMDRyzJmV_y0jrxamC9Bge-nPJ6Sjq5etOrFThAH7bGdqhtsdjXlXwiMUeZvFnhEDwLCdRr-p8kbiQZCvBG4mlpbhn8_aBQ5m55Kv6-PdVC0t_EmAoGuAH_b_cW4KH4lc-SkdLg4HGju3AZ7OdUlku4EI91As2ZS0B-loEjdT56ddVNwE4QuGstSqenOZ6j1I2B4EjIlNr-nyUJpHtPJAgcxKusO6vitwpl8iExFujzZ1KtjSR739lSPaGLHG9mY_a5zc May 27 14:51:28 volumio volumio[1788]: info: Spotify credentials grant success - running version from March 24, 2019 May 27 14:51:28 volumio volumio[1788]: error: Failed to retrieve user informations: Error: connect ECONNREFUSED 127.0.0.1:443 May 27 14:51:28 volumio volumio[1788]: error: Spotify credentials failed to read user data: May 27 14:51:28 volumio volumio[1788]: info: An error occurred while initializing Spotify Browsing facility: May 27 14:51:29 volumio volumio[1788]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 14:51:31 volumio volumio[1788]: info: go-librespot daemon successfully initialized May 27 14:51:33 volumio go-librespot[6852]: time="2025-05-27T14:51:33+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 27 14:51:33 volumio go-librespot[6852]: time="2025-05-27T14:51:33+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 27 14:51:33 volumio go-librespot[6852]: time="2025-05-27T14:51:33+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 27 14:51:33 volumio go-librespot[6852]: time="2025-05-27T14:51:33+02:00" level=info msg="zeroconf server listening on port 40077" May 27 14:51:34 volumio volumio[1788]: info: Initializing connection to go-librespot Websocket May 27 14:51:34 volumio go-librespot[6852]: time="2025-05-27T14:51:34+02:00" level=debug msg="new websocket client" May 27 14:51:34 volumio volumio[1788]: info: Connection to go-librespot Websocket established May 27 14:51:36 volumio volumio[1788]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 27 14:51:36 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 27 14:51:36 volumio volumio[1788]: info: Creating Spotify config file May 27 14:51:36 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 14:51:36 volumio volumio[1788]: info: Spotify config file written May 27 14:51:36 volumio sudo[6874]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 27 14:51:36 volumio sudo[6874]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 14:51:36 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 27 14:51:36 volumio systemd[1]: go-librespot-daemon.service: Killing process 6856 (go-librespot) with signal SIGKILL. May 27 14:51:36 volumio volumio[1788]: info: Connection to go-librespot Websocket closed May 27 14:51:36 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 27 14:51:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 27 14:51:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 27 14:51:36 volumio go-librespot[6876]: go-librespot daemon starting... May 27 14:51:36 volumio sudo[6874]: pam_unix(sudo:session): session closed for user root May 27 14:51:36 volumio go-librespot[6877]: time="2025-05-27T14:51:36+02:00" level=info msg="running go-librespot 0.2.0" May 27 14:51:36 volumio go-librespot[6877]: time="2025-05-27T14:51:36+02:00" level=debug msg="app state loaded" May 27 14:51:36 volumio go-librespot[6877]: time="2025-05-27T14:51:36+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 27 14:51:37 volumio volumio[1788]: info: Getting Spotify volume May 27 14:51:37 volumio volumio[1788]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 May 27 14:51:37 volumio volumio[1788]: info: CoreCommandRouter::volumioGetState May 27 14:51:37 volumio volumio[1788]: info: CorePlayQueue::getTrack 3 May 27 14:51:39 volumio volumio[1788]: info: Initializing connection to go-librespot Websocket May 27 14:51:39 volumio go-librespot[6877]: time="2025-05-27T14:51:39+02:00" level=debug msg="new websocket client" May 27 14:51:39 volumio volumio[1788]: info: Connection to go-librespot Websocket established May 27 14:51:39 volumio volumio[1788]: info: go-librespot daemon successfully initialized May 27 14:51:42 volumio volumio[1788]: info: Getting Spotify volume May 27 14:51:42 volumio volumio[1788]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 27 14:51:42 volumio volumio[1788]: info: CoreCommandRouter::volumioGetState May 27 14:51:42 volumio volumio[1788]: info: CorePlayQueue::getTrack 3 May 27 14:51:42 volumio volumio[1788]: info: Initializing connection to go-librespot Websocket May 27 14:51:42 volumio go-librespot[6877]: time="2025-05-27T14:51:42+02:00" level=debug msg="new websocket client" May 27 14:51:42 volumio volumio[1788]: info: Connection to go-librespot Websocket established May 27 14:51:44 volumio go-librespot[6877]: time="2025-05-27T14:51:44+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 27 14:51:44 volumio go-librespot[6877]: time="2025-05-27T14:51:44+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 27 14:51:44 volumio go-librespot[6877]: time="2025-05-27T14:51:44+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 27 14:51:44 volumio go-librespot[6877]: time="2025-05-27T14:51:44+02:00" level=info msg="zeroconf server listening on port 39231" May 27 14:51:45 volumio volumio[1788]: info: Getting Spotify volume May 27 14:51:45 volumio volumio[1788]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 May 27 14:51:45 volumio volumio[1788]: info: CoreCommandRouter::volumioGetState May 27 14:51:45 volumio volumio[1788]: info: CorePlayQueue::getTrack 3 May 27 14:51:50 volumio go-librespot[6877]: time="2025-05-27T14:51:50+02:00" level=debug msg="obtained new client token: AAB6JjJS1F4C9hYo/3Ek8dWnK8+YrFJ3RZVajz8vT9amDNevHKUqj6LEi2fXTF0zK1WcCkv2V7ar58DRartA+QJlJmnfLoHEA7wlMbRFYNrSLRFSjkz334/I9bIPIvGiEsyoJguoUWU3iw0COkVtvLz0uL+OPceEF77Phc26ofjkl+xrrXblPHq2mc52vjgaCT5xKeVK3bLqet/RhxKQUbjcGCo2DRPWO7/wReFD03MKGgPCDc1QdPPwAA==" May 27 14:51:50 volumio volumio[1788]: info: Received OAUTH Data May 27 14:51:50 volumio volumio[1788]: info: Executing Spotify Oauth Login May 27 14:51:50 volumio volumio[1788]: info: Saving Spotify Refresh Token May 27 14:51:50 volumio volumio[1788]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 27 14:51:50 volumio volumio[1788]: SPOTIFY: BQBCCLN8JWfih6Qn0ucK7_-LHOakqaGShMChW87G5J5T6FT1u3s1vvOXgMrYqjpzFkait7Lqxs0EPOLc_u5B5BLk3M3_BsL7UGnP7Pi6Qb4WOtD6DDRuJaUk0A-p9zUfHbyEHziV9IOEREPHFNy4oPONRhgmj_9DXFNZ-K0qycd_kbA10aCJGk0KH_KnhChJc8HJ-adBOf-kvzIkGUuzEMeFDLtWkd2d6NGj5rgCkhmHrINc4Q2w7Ro2GfI-_NqARSCDJqOaflJRoeOSkfF3R8C9aL_yCaCZzo96B96qxAiWLQc May 27 14:51:50 volumio volumio[1788]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 27 14:51:50 volumio volumio[1788]: info: New Spotify access token = BQBCCLN8JWfih6Qn0ucK7_-LHOakqaGShMChW87G5J5T6FT1u3s1vvOXgMrYqjpzFkait7Lqxs0EPOLc_u5B5BLk3M3_BsL7UGnP7Pi6Qb4WOtD6DDRuJaUk0A-p9zUfHbyEHziV9IOEREPHFNy4oPONRhgmj_9DXFNZ-K0qycd_kbA10aCJGk0KH_KnhChJc8HJ-adBOf-kvzIkGUuzEMeFDLtWkd2d6NGj5rgCkhmHrINc4Q2w7Ro2GfI-_NqARSCDJqOaflJRoeOSkfF3R8C9aL_yCaCZzo96B96qxAiWLQc May 27 14:51:50 volumio volumio[1788]: info: Spotify credentials grant success - running version from March 24, 2019 May 27 14:51:51 volumio volumio[1788]: SPOTIFY: User informations: {"country":"IT","display_name":"dalnihifi","email":"dalnihifi@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31wjxdhd2pn6hlzahmg4vgavgnki"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31wjxdhd2pn6hlzahmg4vgavgnki","id":"31wjxdhd2pn6hlzahmg4vgavgnki","images":[],"product":"free","type":"user","uri":"spotify:user:31wjxdhd2pn6hlzahmg4vgavgnki"} May 27 14:51:51 volumio volumio[1788]: info: Creating Spotify config file May 27 14:51:51 volumio volumio[1788]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 14:51:51 volumio volumio[1788]: info: Spotify config file written May 27 14:51:51 volumio sudo[6912]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 27 14:51:51 volumio sudo[6912]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 14:51:51 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 27 14:51:51 volumio volumio[1788]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 14:51:51 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 27 14:51:51 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 27 14:51:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 27 14:51:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 27 14:51:51 volumio volumio[1788]: Error: socket hang up May 27 14:51:51 volumio volumio[1788]: at connResetException (node:internal/errors:720:14) May 27 14:51:51 volumio volumio[1788]: at Socket.socketOnEnd (node:_http_client:519:23) May 27 14:51:51 volumio volumio[1788]: at Socket.emit (node:events:526:35) May 27 14:51:51 volumio volumio[1788]: at endReadableNT (node:internal/streams/readable:1376:12) May 27 14:51:51 volumio volumio[1788]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { May 27 14:51:51 volumio volumio[1788]: code: 'ECONNRESET', May 27 14:51:51 volumio volumio[1788]: response: undefined May 27 14:51:51 volumio volumio[1788]: } May 27 14:51:51 volumio volumio[1788]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 14:51:51 volumio sudo[6912]: pam_unix(sudo:session): session closed for user root May 27 14:51:51 volumio go-librespot[6917]: go-librespot daemon starting... May 27 14:51:51 volumio dbus-daemon[608]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.87' (uid=0 pid=6915 comm="timedatectl show --property=NTPSynchronized --valu") May 27 14:51:51 volumio go-librespot[6918]: time="2025-05-27T14:51:51+02:00" level=info msg="running go-librespot 0.2.0" May 27 14:51:51 volumio go-librespot[6918]: time="2025-05-27T14:51:51+02:00" level=debug msg="app state loaded" May 27 14:51:51 volumio go-librespot[6918]: time="2025-05-27T14:51:51+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 27 14:51:51 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 27 14:51:51 volumio dbus-daemon[608]: [system] Successfully activated service 'org.freedesktop.timedate1' May 27 14:51:51 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. May 27 14:51:51 volumio setdatetime-helper.sh[6914]: Time is already synchronized. May 27 14:51:51 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 27 14:51:51 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 27 14:51:51 volumio sudo[6938]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-05-27 14:50' May 27 14:51:51 volumio sudo[6938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="fd567ba9bc0dc34c0403e2d5b72a0f46467d1983" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri May 23 07:33:33 UTC 2025" VOLUMIO_VERSION="0.069" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="d67a2da4ffe3f001e986b1f31eaa3a76"