Mar 24 23:37:00 musicvolumio volumio[1245]: info: Initializing connection to go-librespot Websocket Mar 24 23:37:00 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:00+01:00" level=debug msg="new websocket client" Mar 24 23:37:00 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket established Mar 24 23:37:00 musicvolumio volumio[1245]: info: Getting Spotify volume Mar 24 23:37:00 musicvolumio volumio[1245]: info: Spotify volume: 100 Mar 24 23:37:00 musicvolumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 24 23:37:00 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:00 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:02 musicvolumio volumio[1245]: info: Getting Spotify volume Mar 24 23:37:02 musicvolumio volumio[1245]: info: Spotify volume: 100 Mar 24 23:37:02 musicvolumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 24 23:37:02 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:02 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:03 musicvolumio volumio[1245]: info: Getting Spotify volume Mar 24 23:37:03 musicvolumio volumio[1245]: info: Spotify volume: 100 Mar 24 23:37:03 musicvolumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 24 23:37:03 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:03 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=debug msg="handling play player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E4tEzSpqXQK7W" Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E4tEzSpqXQK7W" Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:4JGozY7PWUikJ3qJ1Egef8" Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=trace msg="emitting websocket event: will_play" Mar 24 23:37:07 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:07 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:07 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:07 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:07 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=debug msg="selected format OGG_VORBIS_160 (cab6cf3f7ce4f7a5ae327b007b6055485b8d72b5)" uri="spotify:track:4JGozY7PWUikJ3qJ1Egef8" Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=debug msg="requested aes key for file cab6cf3f7ce4f7a5ae327b007b6055485b8d72b5, gid: 4JGozY7PWUikJ3qJ1Egef8" Mar 24 23:37:07 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:07+01:00" level=warning msg="failed handling dealer request" error="failed loading current track (load context): failed creating stream for spotify:track:4JGozY7PWUikJ3qJ1Egef8: failed retrieving audio key: failed retrieving aes key with code 1" Mar 24 23:37:18 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=info msg="playback was transferred to 25010PN30G" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1230" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 460" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="put connect state inactive" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=trace msg="emitting websocket event: inactive" Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"inactive","data":null} Mar 24 23:37:19 musicvolumio volumio[1245]: error: Failed to decode event: inactive Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"inactive","data":null} Mar 24 23:37:19 musicvolumio volumio[1245]: error: Failed to decode event: inactive Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=trace msg="emitting websocket event: stopped" Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"inactive","data":null} Mar 24 23:37:19 musicvolumio volumio[1245]: error: Failed to decode event: inactive Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: PUSH STATE SPOTIFY Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::servicePushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: CURRENT POSITION 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState stateService stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: No code Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.297+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.298+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.298+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.299+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.299+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.300+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"inactive","data":null} Mar 24 23:37:19 musicvolumio volumio[1245]: error: Failed to decode event: inactive Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: PUSH STATE SPOTIFY Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::servicePushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: CURRENT POSITION 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState stateService stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: No code Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.315+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.315+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.316+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.316+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.318+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.318+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="dealer connection closed" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="dealer recv loop stopped" Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"inactive","data":null} Mar 24 23:37:19 musicvolumio volumio[1245]: error: Failed to decode event: inactive Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: PUSH STATE SPOTIFY Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::servicePushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: CURRENT POSITION 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState stateService stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: No code Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.333+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.334+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.335+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.335+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19760 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.336+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.337+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: PUSH STATE SPOTIFY Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::servicePushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: CURRENT POSITION 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState stateService stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: No code Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.349+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19959 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.350+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19959 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.351+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19959 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.352+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.353+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.354+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: PUSH STATE SPOTIFY Mar 24 23:37:19 musicvolumio volumio[1245]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::servicePushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 24 23:37:19 musicvolumio volumio[1245]: verbose: CURRENT POSITION 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState stateService stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: No code Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreStateMachine::pushState Mar 24 23:37:19 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:19 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushState Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.368+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19959 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.369+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19959 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.369+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="obtained new client token: AABQ2nuGSHvUn7V68w8xUyE5FtWxpH21ZgMeI7HpC+9POOt1NhzTUFnyXfu2enAu7Hi59Qew46qKxtfi0Zpg3KAj0vQF7pDvBXqPmxLkY+wMJFHeEHx/I1E6h5pZiNVKbyzdRjRcs8ozCFb8jNHsfS4BSWEuxLK4nKIyln/Eo+xIlKFoFuxADER36S7g8Y1IPIMbTmBN8AqrVvwuT//AdCsTp4r/y0lA/YIqCAUTmJkv1QyjTdPvHbQ=" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.373+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.373+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" state=STATUS_STOPPED positionMs=19959 volume=100 Mar 24 23:37:19 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:19.377+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" id=spotify:track:0uAnrNNITY7KwmOqdVEsIK title="MADAME - L'anima" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="completed keyexchange" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="completed challenge" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=info msg="authenticated AP" username="31************************va" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=info msg="authenticated Login5" username="31************************va" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="restored session after logout" username="31************************va" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="dealer connection opened" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=trace msg="starting accesspoint recv loop" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=trace msg="starting dealer recv loop" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=trace msg="received accesspoint ping" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="received connection id: OGQ1YmZmNGItNjIy...QTJDNkMzRjExMA==" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=trace msg="received accesspoint pong ack" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 24 23:37:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:19+01:00" level=debug msg="update volume requested to 65535/65535" Mar 24 23:37:20 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:20+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 24 23:37:20 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:20+01:00" level=trace msg="emitting websocket event: volume" Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Mar 24 23:37:20 musicvolumio volumio[1245]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Mar 24 23:37:22 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 24 23:37:24 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="handling transfer player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E4tEzSpqXQK7W" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E4tEzSpqXQK7W" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="loading track (paused: false, position: 2928ms)" uri="spotify:track:4JGozY7PWUikJ3qJ1Egef8" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=trace msg="emitting websocket event: will_play" Mar 24 23:37:25 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:25 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:25 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:25 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1172" Mar 24 23:37:25 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E4tEzSpqXQK7W","uri":"spotify:track:4JGozY7PWUikJ3qJ1Egef8","play_origin":"playlist"}} Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="selected format OGG_VORBIS_160 (cab6cf3f7ce4f7a5ae327b007b6055485b8d72b5)" uri="spotify:track:4JGozY7PWUikJ3qJ1Egef8" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="requested aes key for file cab6cf3f7ce4f7a5ae327b007b6055485b8d72b5, gid: 4JGozY7PWUikJ3qJ1Egef8" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:4JGozY7PWUikJ3qJ1Egef8: failed retrieving audio key: failed retrieving aes key with code 1" Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 24 23:37:25 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:25+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 24 23:37:30 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 24 23:37:35 musicvolumio volumio5-onboarding[1829]: time=2026-03-24T23:37:35.726+01:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.214:57462,00:00:00:00:00:00%06 @ 0x2838420" latency=497.225553ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Mar 24 23:37:36 musicvolumio sudo[8102]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 23:37:36 musicvolumio sudo[8102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:37:36 musicvolumio sudo[8102]: pam_unix(sudo:session): session closed for user root Mar 24 23:37:36 musicvolumio sudo[8104]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 23:37:36 musicvolumio sudo[8104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:37:36 musicvolumio sudo[8104]: pam_unix(sudo:session): session closed for user root Mar 24 23:37:36 musicvolumio volumio[1245]: verbose: New Socket.io Connection to 192.168.0.74 from 192.168.0.214 UA: Mozilla/5.0 (Linux; Android 16; 25010PN30G Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.159 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Mar 24 23:37:36 musicvolumio sudo[8108]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 23:37:36 musicvolumio sudo[8108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:37:36 musicvolumio sudo[8108]: pam_unix(sudo:session): session closed for user root Mar 24 23:37:36 musicvolumio sudo[8110]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 23:37:36 musicvolumio sudo[8110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:37:36 musicvolumio sudo[8110]: pam_unix(sudo:session): session closed for user root Mar 24 23:37:36 musicvolumio volumio[1245]: verbose: New Socket.io Connection to 192.168.0.74 from 192.168.0.214 UA: Mozilla/5.0 (Linux; Android 16; 25010PN30G Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.159 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetVisibleSources Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:36 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 24 23:37:36 musicvolumio volumio[1245]: info: Received Get System Info Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 24 23:37:36 musicvolumio volumio[1245]: info: Discovery: Getting this device information Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:36 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:36 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:36 musicvolumio volumio[1245]: info: Listing playlists Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 24 23:37:36 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 24 23:37:36 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 24 23:37:37 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 24 23:37:38 musicvolumio volumio[1245]: info: Received Get System Info Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 24 23:37:38 musicvolumio volumio[1245]: info: Discovery: Getting this device information Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:38 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 24 23:37:38 musicvolumio volumio[1245]: info: Received Get System Info Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 24 23:37:38 musicvolumio volumio[1245]: info: Discovery: Getting this device information Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:38 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:38 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 24 23:37:42 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetQueue Mar 24 23:37:42 musicvolumio volumio[1245]: info: CoreStateMachine::getQueue Mar 24 23:37:42 musicvolumio volumio[1245]: info: CorePlayQueue::getQueue Mar 24 23:37:43 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 24 23:37:46 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 24 23:37:47 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 24 23:37:47 musicvolumio volumio[1245]: info: In handleBrowseUri, curUri=spotify Mar 24 23:37:47 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:47 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:47 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:47 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:49 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:49+01:00" level=trace msg="sent dealer ping" Mar 24 23:37:49 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:49+01:00" level=trace msg="received dealer pong" Mar 24 23:37:50 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 24 23:37:50 musicvolumio volumio[1245]: info: In handleBrowseUri, curUri=spotify/playlists Mar 24 23:37:50 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:52 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 24 23:37:52 musicvolumio volumio[1245]: info: In handleBrowseUri, curUri=spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 24 23:37:52 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 24 23:37:54 musicvolumio volumio[1245]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 24 23:37:54 musicvolumio volumio[1245]: info: Received Get System Version Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 23:37:54 musicvolumio volumio[1245]: info: Received Get System Info Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 24 23:37:54 musicvolumio volumio[1245]: info: Discovery: Getting this device information Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 24 23:37:54 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::ClearQueue Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::stop Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::clearPlayQueue Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::saveQueue Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::addQueueItems Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::addQueueItems Mar 24 23:37:54 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:54 musicvolumio volumio[1245]: info: Adding Item to queue: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 24 23:37:54 musicvolumio volumio[1245]: info: Using cached record of: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::saveQueue Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::updateTrackBlock Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::getTrackBlock Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPlay Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::play index 0 Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::stop Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::play index undefined Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:54 musicvolumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer Mar 24 23:37:54 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:54 musicvolumio volumio[1245]: info: [1774391874447] ControllerSpotify::clearAddPlayTrack Mar 24 23:37:54 musicvolumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play Mar 24 23:37:54 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:54+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:54 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:54+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:54 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:54+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:54 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 24 23:37:54 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:54+01:00" level=trace msg="emitting websocket event: will_play" Mar 24 23:37:54 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:54 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:54 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:54 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:54 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:54 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:54+01:00" level=debug msg="selected format OGG_VORBIS_160 (74672e235b00a76c6b23960d5b84d2c6e9feb797)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:54 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:54+01:00" level=debug msg="requested aes key for file 74672e235b00a76c6b23960d5b84d2c6e9feb797, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:54 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:54+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 24 23:37:54 musicvolumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 24 23:37:55 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::ClearQueue Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::stop Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:37:55 musicvolumio volumio[1245]: info: CorePlayQueue::clearPlayQueue Mar 24 23:37:55 musicvolumio volumio[1245]: info: CorePlayQueue::saveQueue Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::addQueueItems Mar 24 23:37:55 musicvolumio volumio[1245]: info: CorePlayQueue::addQueueItems Mar 24 23:37:55 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:37:55 musicvolumio volumio[1245]: info: Adding Item to queue: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 24 23:37:55 musicvolumio volumio[1245]: info: Using cached record of: spotify:user:spotify:playlist:1w9zj6hIdYFSTzMFlV8zJ8 Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue Mar 24 23:37:55 musicvolumio volumio[1245]: info: CorePlayQueue::saveQueue Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::updateTrackBlock Mar 24 23:37:55 musicvolumio volumio[1245]: info: CorePlayQueue::getTrackBlock Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:37:55 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPlay Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::play index 0 Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::stop Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::play index undefined Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:37:55 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:55 musicvolumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer Mar 24 23:37:55 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:37:55 musicvolumio volumio[1245]: info: [1774391875270] ControllerSpotify::clearAddPlayTrack Mar 24 23:37:55 musicvolumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play Mar 24 23:37:55 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:55+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:55 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:55+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:55 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:55+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:55 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:55+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 24 23:37:55 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:55+01:00" level=trace msg="emitting websocket event: will_play" Mar 24 23:37:55 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:55 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:55 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:55 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:55 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:37:55 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:55+01:00" level=debug msg="selected format OGG_VORBIS_160 (74672e235b00a76c6b23960d5b84d2c6e9feb797)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:55 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:55+01:00" level=debug msg="requested aes key for file 74672e235b00a76c6b23960d5b84d2c6e9feb797, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:37:55 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:55+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 24 23:37:55 musicvolumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 24 23:37:58 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:58+01:00" level=debug msg="handling pause player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 24 23:37:58 musicvolumio go-librespot[8027]: time="2026-03-24T23:37:58+01:00" level=warning msg="failed handling dealer request" error="no primary stream" Mar 24 23:38:02 musicvolumio go-librespot[8027]: time="2026-03-24T23:38:02+01:00" level=debug msg="handling pause player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 24 23:38:02 musicvolumio go-librespot[8027]: time="2026-03-24T23:38:02+01:00" level=warning msg="failed handling dealer request" error="no primary stream" Mar 24 23:38:03 musicvolumio go-librespot[8027]: time="2026-03-24T23:38:03+01:00" level=debug msg="handling resume player command from 02b98784190d906f5d28f3e1065c4808ca9c5033" Mar 24 23:38:03 musicvolumio go-librespot[8027]: time="2026-03-24T23:38:03+01:00" level=warning msg="failed handling dealer request" error="no primary stream" Mar 24 23:38:11 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Mar 24 23:38:11 musicvolumio volumio[1245]: info: CURURI: artists:// Mar 24 23:38:11 musicvolumio volumio[1245]: info: Preload queue cleared Mar 24 23:38:16 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 24 23:38:16 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 24 23:38:16 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 24 23:38:19 musicvolumio volumio[1245]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 24 23:38:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:38:19+01:00" level=trace msg="sent dealer ping" Mar 24 23:38:19 musicvolumio go-librespot[8027]: time="2026-03-24T23:38:19+01:00" level=trace msg="received dealer pong" Mar 24 23:38:20 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 24 23:38:24 musicvolumio kernel: hwmon hwmon1: Undervoltage detected! Mar 24 23:38:31 musicvolumio kernel: hwmon hwmon1: Voltage normalised Mar 24 23:38:40 musicvolumio volumio[1245]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 24 23:38:40 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 24 23:38:40 musicvolumio volumio[1245]: info: Creating Spotify config file Mar 24 23:38:40 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 23:38:40 musicvolumio volumio[1245]: info: Spotify config file written Mar 24 23:38:40 musicvolumio sudo[8256]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 23:38:40 musicvolumio sudo[8256]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:38:40 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 23:38:40 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 8032 (go-librespot) with signal SIGKILL. Mar 24 23:38:40 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 23:38:40 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:40 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:40 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:40 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:40 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:40 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:40 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:40 musicvolumio go-librespot[8258]: go-librespot daemon starting... Mar 24 23:38:40 musicvolumio sudo[8256]: pam_unix(sudo:session): session closed for user root Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=debug msg="app state loaded" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01: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]" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01: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]" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01: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]" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=info msg="zeroconf server listening on port 35759" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=debug msg="obtained new client token: AAD3q3tIMB+7Ebk6TvvbJV36NmH/9pdQSQPQU2O7cPN+sMR9AONLa3npmKK2U9bDmZlHKjoDfGY1JJ2VZm0bcudetYqsov08JlKXUk8pyhV0F4+eeVXMQSzi4c02rEy7oDRK8SbJgGk8dZ6i9dqS8b9+so+TU8psGLkUgR7xRyi6G8gPv30nVFotfU4b1f+KPeMVFUFSDJBzz9FOVH+a7uZf5RNL0xD3qcfNviHfnzrIXGU8CB6dRjo=" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=debug msg="completed keyexchange" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=debug msg="completed challenge" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=info msg="authenticated AP" username="31************************va" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=info msg="authenticated Login5" username="31************************va" Mar 24 23:38:40 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:40+01:00" level=debug msg="initializing zeroconf session" username="31************************va" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="dealer connection opened" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=trace msg="starting accesspoint recv loop" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=trace msg="starting dealer recv loop" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=trace msg="received accesspoint ping" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="received connection id: MWJkMjFlYTMtMDRh...RTVBMTczMTM5NA==" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=trace msg="received accesspoint pong ack" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="update volume requested to 65535/65535" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 24 23:38:41 musicvolumio go-librespot[8259]: time="2026-03-24T23:38:41+01:00" level=trace msg="emitting websocket event: volume" Mar 24 23:38:42 musicvolumio volumio[1245]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 24 23:38:42 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 24 23:38:42 musicvolumio volumio[1245]: info: Creating Spotify config file Mar 24 23:38:42 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 23:38:42 musicvolumio volumio[1245]: info: Spotify config file written Mar 24 23:38:42 musicvolumio sudo[8269]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 23:38:42 musicvolumio sudo[8269]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:38:42 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 23:38:42 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 8262 (go-librespot) with signal SIGKILL. Mar 24 23:38:42 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 23:38:42 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:42 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:42 musicvolumio go-librespot[8271]: go-librespot daemon starting... Mar 24 23:38:42 musicvolumio sudo[8269]: pam_unix(sudo:session): session closed for user root Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=debug msg="app state loaded" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01: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-gew1.spotify.com:80]" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=info msg="zeroconf server listening on port 39833" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=debug msg="obtained new client token: AAAQ0nnJeJN/ZKORLjQRduR+chiBWN2aGrJDS0s4SvkZoXGYUudmUPfKUi7tmy4MOm1Hcwt0cpmXnOPpO56MipQxQYDJ+SAwhESz3M+sQsQ/JcGGj7m6LsCQAk7tmrwdPi55ohy6wmM9bl+Xpv5DbTcPAAg8DW4jC6rmh38L6pHnwSU6E+hF523KDAMAngslghIlbH40oaq6WvDH+pnjJ3yJ63yjRvLUhtmWzeaa+tGYGvQ/Joc3pSM=" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=debug msg="completed keyexchange" Mar 24 23:38:42 musicvolumio go-librespot[8272]: time="2026-03-24T23:38:42+01:00" level=debug msg="completed challenge" Mar 24 23:38:42 musicvolumio volumio[1245]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 24 23:38:42 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 24 23:38:42 musicvolumio volumio[1245]: info: Creating Spotify config file Mar 24 23:38:42 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 23:38:42 musicvolumio volumio[1245]: info: Spotify config file written Mar 24 23:38:42 musicvolumio sudo[8282]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 23:38:42 musicvolumio sudo[8282]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:38:42 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 23:38:42 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 8277 (go-librespot) with signal SIGKILL. Mar 24 23:38:42 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 23:38:42 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:42 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:42 musicvolumio go-librespot[8284]: go-librespot daemon starting... Mar 24 23:38:42 musicvolumio sudo[8282]: pam_unix(sudo:session): session closed for user root Mar 24 23:38:42 musicvolumio go-librespot[8285]: time="2026-03-24T23:38:42+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 23:38:42 musicvolumio go-librespot[8285]: time="2026-03-24T23:38:42+01:00" level=debug msg="app state loaded" Mar 24 23:38:42 musicvolumio go-librespot[8285]: time="2026-03-24T23:38:42+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 23:38:42 musicvolumio volumio[1245]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 24 23:38:42 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 24 23:38:42 musicvolumio volumio[1245]: info: Creating Spotify config file Mar 24 23:38:42 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 23:38:42 musicvolumio volumio[1245]: info: Spotify config file written Mar 24 23:38:42 musicvolumio sudo[8294]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 23:38:42 musicvolumio sudo[8294]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:38:42 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 23:38:42 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 8287 (go-librespot) with signal SIGKILL. Mar 24 23:38:42 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 23:38:42 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:43 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:43 musicvolumio go-librespot[8297]: go-librespot daemon starting... Mar 24 23:38:43 musicvolumio sudo[8294]: pam_unix(sudo:session): session closed for user root Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=debug msg="app state loaded" Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01: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-gew1.spotify.com:80]" Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=info msg="zeroconf server listening on port 39439" Mar 24 23:38:43 musicvolumio volumio[1245]: info: Initializing connection to go-librespot Websocket Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=debug msg="new websocket client" Mar 24 23:38:43 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket established Mar 24 23:38:43 musicvolumio volumio[1245]: info: go-librespot daemon successfully initialized Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=debug msg="obtained new client token: AAB9GyTt5VvS1FHneZPpByF3GfMKO6nRrOt0rXfuMIZJ1oyoqPGNd5AkpiusmisHmOCoVNvpsNHeeXU8FLymPVov3FH6Q5YHiaRMJX1YKd4gsk1SkzvG4o+12g3YlXe93D9Q47qtyGzfvebOlSayTBTFwpKBGE34iTACFRNCdHjWoWFSoVIH1ZDb+P4fnOAYqhmx5UzOz5N44so4JVmAcFkKhy05AvlkacRnQEKEXONcjxS5zmdMexE=" Mar 24 23:38:43 musicvolumio volumio[1245]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 24 23:38:43 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 24 23:38:43 musicvolumio volumio[1245]: info: Creating Spotify config file Mar 24 23:38:43 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 23:38:43 musicvolumio volumio[1245]: info: Spotify config file written Mar 24 23:38:43 musicvolumio go-librespot[8298]: time="2026-03-24T23:38:43+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 23:38:43 musicvolumio sudo[8308]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 23:38:43 musicvolumio sudo[8308]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:38:43 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 23:38:43 musicvolumio systemd[1]: go-librespot-daemon.service: Killing process 8301 (go-librespot) with signal SIGKILL. Mar 24 23:38:43 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:43 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 23:38:43 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:43 musicvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:43 musicvolumio go-librespot[8310]: go-librespot daemon starting... Mar 24 23:38:43 musicvolumio sudo[8308]: pam_unix(sudo:session): session closed for user root Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=debug msg="app state loaded" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01: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]" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01: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]" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01: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]" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=info msg="zeroconf server listening on port 40189" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=debug msg="obtained new client token: AAA3zmULj3iC707JCwepGrhCjv6zr+vnTmAT5PnKd9OOFgmG3NLrcRrsEe9M1tn7oi+lSUuQEMAkhfIvkXvMRztL3OpMiJi2ykAwsgmV8lO9ONrR7bqDMi0ctgoXA4hUgybXGYPgD0HU8S5QYTUDYroNA67FXKvEmtijz3nNPhzPcMsAIZ8eS7eCyRNVX4F8ZTSgHlZ+dOVAKRpHS0hOIMfQx9xXLPDocmCptgoI1ptrLVfQ516uhx8=" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=debug msg="completed keyexchange" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=debug msg="completed challenge" Mar 24 23:38:43 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:43+01:00" level=info msg="authenticated AP" username="31************************va" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=info msg="authenticated Login5" username="31************************va" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="initializing zeroconf session" username="31************************va" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="dealer connection opened" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=trace msg="starting accesspoint recv loop" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=trace msg="starting dealer recv loop" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=trace msg="received accesspoint ping" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="received connection id: NGE5ZjVlNWMtNmJi...NTBGQjBFOTEwNA==" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=trace msg="received accesspoint pong ack" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="update volume requested to 65535/65535" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 24 23:38:44 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:44+01:00" level=trace msg="emitting websocket event: volume" Mar 24 23:38:45 musicvolumio volumio[1245]: info: go-librespot daemon successfully initialized Mar 24 23:38:45 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:38:45 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:45 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 24 23:38:45 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPlay Mar 24 23:38:45 musicvolumio volumio[1245]: info: CoreStateMachine::play index undefined Mar 24 23:38:45 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:38:45 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:45 musicvolumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer Mar 24 23:38:45 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:45 musicvolumio volumio[1245]: info: [1774391925835] ControllerSpotify::clearAddPlayTrack Mar 24 23:38:45 musicvolumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play Mar 24 23:38:45 musicvolumio volumio[1245]: info: go-librespot daemon successfully initialized Mar 24 23:38:45 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:45+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:45 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:45+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:45 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:45+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:45 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:45+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 24 23:38:45 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:45+01:00" level=trace msg="emitting websocket event: will_play" Mar 24 23:38:46 musicvolumio volumio[1245]: info: go-librespot daemon successfully initialized Mar 24 23:38:46 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:46+01:00" level=debug msg="selected format OGG_VORBIS_96 (6d440efab2f86ad3103ad9599ba2ffecb8d33b6c)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:46 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:46+01:00" level=debug msg="requested aes key for file 6d440efab2f86ad3103ad9599ba2ffecb8d33b6c, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:46 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:46+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 24 23:38:46 musicvolumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 24 23:38:46 musicvolumio volumio[1245]: info: Getting Spotify volume Mar 24 23:38:46 musicvolumio volumio[1245]: info: Spotify volume: 100 Mar 24 23:38:46 musicvolumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Mar 24 23:38:46 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:38:46 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:46 musicvolumio volumio[1245]: info: Initializing connection to go-librespot Websocket Mar 24 23:38:46 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:46+01:00" level=debug msg="new websocket client" Mar 24 23:38:46 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket established Mar 24 23:38:46 musicvolumio volumio[1245]: info: Initializing connection to go-librespot Websocket Mar 24 23:38:46 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:46+01:00" level=debug msg="new websocket client" Mar 24 23:38:46 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket established Mar 24 23:38:46 musicvolumio volumio[1245]: info: go-librespot daemon successfully initialized Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:38:47 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPlay Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreStateMachine::play index undefined Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:38:47 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer Mar 24 23:38:47 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:47 musicvolumio volumio[1245]: info: [1774391927172] ControllerSpotify::clearAddPlayTrack Mar 24 23:38:47 musicvolumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=trace msg="emitting websocket event: will_play" Mar 24 23:38:47 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:38:47 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="selected format OGG_VORBIS_96 (6d440efab2f86ad3103ad9599ba2ffecb8d33b6c)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="requested aes key for file 6d440efab2f86ad3103ad9599ba2ffecb8d33b6c, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 24 23:38:47 musicvolumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioGetState Mar 24 23:38:47 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreCommandRouter::volumioPlay Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreStateMachine::play index undefined Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 24 23:38:47 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:47 musicvolumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer Mar 24 23:38:47 musicvolumio volumio[1245]: info: CorePlayQueue::getTrack 0 Mar 24 23:38:47 musicvolumio volumio[1245]: info: [1774391927484] ControllerSpotify::clearAddPlayTrack Mar 24 23:38:47 musicvolumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="resolved context of track" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=trace msg="emitting websocket event: will_play" Mar 24 23:38:47 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:38:47 musicvolumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","play_origin":"go-librespot"}} Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="selected format OGG_VORBIS_96 (6d440efab2f86ad3103ad9599ba2ffecb8d33b6c)" uri="spotify:track:7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=debug msg="requested aes key for file 6d440efab2f86ad3103ad9599ba2ffecb8d33b6c, gid: 7J1uxwnxfQLu4APicE5Rnj" Mar 24 23:38:47 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:47+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:7J1uxwnxfQLu4APicE5Rnj: failed retrieving audio key: failed retrieving aes key with code 1" Mar 24 23:38:47 musicvolumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 24 23:38:48 musicvolumio volumio[1245]: info: Initializing connection to go-librespot Websocket Mar 24 23:38:48 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:48+01:00" level=debug msg="new websocket client" Mar 24 23:38:48 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket established Mar 24 23:38:48 musicvolumio volumio[1245]: info: Initializing connection to go-librespot Websocket Mar 24 23:38:48 musicvolumio go-librespot[8311]: time="2026-03-24T23:38:48+01:00" level=debug msg="new websocket client" Mar 24 23:38:48 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket established Mar 24 23:38:48 musicvolumio volumio[1245]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 24 23:38:48 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 24 23:38:48 musicvolumio volumio[1245]: info: Creating Spotify config file Mar 24 23:38:48 musicvolumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 23:38:48 musicvolumio volumio[1245]: info: Spotify config file written Mar 24 23:38:48 musicvolumio sudo[8343]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 23:38:48 musicvolumio sudo[8343]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 23:38:48 musicvolumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 23:38:48 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:48 musicvolumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 23:38:48 musicvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:48 musicvolumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 24 23:38:48 musicvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 24 23:38:48 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:48 musicvolumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 24 23:38:48 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:48 musicvolumio volumio[1245]: info: Connection to go-librespot Websocket closed Mar 24 23:38:48 musicvolumio sudo[8343]: pam_unix(sudo:session): session closed for user root Mar 24 23:38:48 musicvolumio volumio[1245]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 24 23:38:48 musicvolumio volumio[1245]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 24 23:38:48 musicvolumio volumio[1245]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 24 23:38:48 musicvolumio volumio[1245]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 24 23:38:48 musicvolumio volumio[1245]: followed by "systemctl start go-librespot-daemon.service" again. Mar 24 23:38:48 musicvolumio volumio[1245]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 24 23:38:48 musicvolumio volumio[1245]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 24 23:38:48 musicvolumio volumio[1245]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 24 23:38:48 musicvolumio volumio[1245]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 24 23:38:48 musicvolumio volumio[1245]: followed by "systemctl start go-librespot-daemon.service" again. Mar 24 23:38:49 musicvolumio volumio[1245]: info: Initializing connection to go-librespot Websocket Mar 24 23:38:49 musicvolumio volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 23:38:49 musicvolumio volumio[1245]: info: Getting Spotify volume Mar 24 23:38:49 musicvolumio volumio[1245]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 23:38:49 musicvolumio volumio[1245]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 23:38:49 musicvolumio volumio[1245]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 24 23:38:49 musicvolumio volumio[1245]: errno: -111, Mar 24 23:38:49 musicvolumio volumio[1245]: code: 'ECONNREFUSED', Mar 24 23:38:49 musicvolumio volumio[1245]: syscall: 'connect', Mar 24 23:38:49 musicvolumio volumio[1245]: address: '127.0.0.1', Mar 24 23:38:49 musicvolumio volumio[1245]: port: 9879, Mar 24 23:38:49 musicvolumio volumio[1245]: response: undefined Mar 24 23:38:49 musicvolumio volumio[1245]: } Mar 24 23:38:49 musicvolumio volumio[1245]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 23:38:49 musicvolumio sudo[8359]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 23:37' Mar 24 23:38:49 musicvolumio sudo[8359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"