Mar 27 14:45:02 werkstatt go-librespot[14913]: time="2026-03-27T14:45:02+01:00" level=trace msg="sent dealer ping" Mar 27 14:45:02 werkstatt go-librespot[14913]: time="2026-03-27T14:45:02+01:00" level=trace msg="received dealer pong" Mar 27 14:45:31 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPlay Mar 27 14:45:31 werkstatt volumio[18826]: info: CoreStateMachine::play index undefined Mar 27 14:45:31 werkstatt volumio[18826]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 14:45:31 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:45:31 werkstatt volumio[18826]: info: CoreStateMachine::startPlaybackTimer Mar 27 14:45:31 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:45:31 werkstatt volumio[18826]: info: [1774619131773] ControllerSpotify::clearAddPlayTrack Mar 27 14:45:31 werkstatt volumio[18826]: info: Sending Spotify command with payload to local API: /player/play Mar 27 14:45:31 werkstatt go-librespot[14913]: time="2026-03-27T14:45:31+01:00" level=debug msg="resolved context of track" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:31 werkstatt go-librespot[14913]: time="2026-03-27T14:45:31+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:31 werkstatt go-librespot[14913]: time="2026-03-27T14:45:31+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:31 werkstatt go-librespot[14913]: time="2026-03-27T14:45:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 14:45:31 werkstatt go-librespot[14913]: time="2026-03-27T14:45:31+01:00" level=trace msg="emitting websocket event: will_play" Mar 27 14:45:31 werkstatt volumio[18826]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0AzjHFbG87tJ0JM6hJ2bve","uri":"spotify:track:0AzjHFbG87tJ0JM6hJ2bve","play_origin":"go-librespot"}} Mar 27 14:45:31 werkstatt go-librespot[14913]: time="2026-03-27T14:45:31+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:0AzjHFbG87tJ0JM6hJ2bve: media is restricted" Mar 27 14:45:31 werkstatt volumio[18826]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 27 14:45:32 werkstatt go-librespot[14913]: time="2026-03-27T14:45:32+01:00" level=trace msg="sent dealer ping" Mar 27 14:45:32 werkstatt go-librespot[14913]: time="2026-03-27T14:45:32+01:00" level=trace msg="received dealer pong" Mar 27 14:45:41 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPrevious Mar 27 14:45:41 werkstatt volumio[18826]: info: CoreStateMachine::previous Mar 27 14:45:41 werkstatt volumio[18826]: info: CoreStateMachine::updateTrackBlock Mar 27 14:45:41 werkstatt volumio[18826]: info: CorePlayQueue::getTrackBlock Mar 27 14:45:41 werkstatt volumio[18826]: info: CoreStateMachine::pushState Mar 27 14:45:41 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:41 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 14:45:41 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPushState Mar 27 14:45:41 werkstatt volumio[18826]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Mar 27 14:45:45 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPlay Mar 27 14:45:45 werkstatt volumio[18826]: info: CoreStateMachine::play index undefined Mar 27 14:45:45 werkstatt volumio[18826]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 14:45:45 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:45 werkstatt volumio[18826]: info: CoreStateMachine::startPlaybackTimer Mar 27 14:45:45 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:45 werkstatt volumio[18826]: info: [1774619145321] ControllerSpotify::clearAddPlayTrack Mar 27 14:45:45 werkstatt volumio[18826]: info: Sending Spotify command with payload to local API: /player/play Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="resolved context of track" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=trace msg="emitting websocket event: will_play" Mar 27 14:45:45 werkstatt volumio[18826]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7I3FfuDaoOUiloIuycnE3W","uri":"spotify:track:7I3FfuDaoOUiloIuycnE3W","play_origin":"go-librespot"}} Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="selected format OGG_VORBIS_160 (0aca7881704ef6200f1af5e601ef1f0da0f74763)" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="requested aes key for file 0aca7881704ef6200f1af5e601ef1f0da0f74763, gid: 0bGJ14HHArD8n3FKqElIik" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="fetched first chunk of 12, total size is 6289308 bytes" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=info msg="loaded track \"Swoon - Boys Noize Summer Remix\" (paused: false, position: 0ms, duration: 321174ms, prefetched: false)" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=trace msg="scheduling prefetch in 291s" Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=trace msg="emitting websocket event: metadata" Mar 27 14:45:45 werkstatt volumio[18826]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0bGJ14HHArD8n3FKqElIik","name":"Swoon - Boys Noize Summer Remix","artist_names":["The Chemical Brothers","Boys Noize"],"album_name":"Another World","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026751335513339370f2ee44c4","position":0,"duration":321174,"release_date":"year:2010 month:1 day:1","track_number":2,"disc_number":1}} Mar 27 14:45:45 werkstatt go-librespot[14913]: time="2026-03-27T14:45:45+01:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:46 werkstatt go-librespot[14913]: time="2026-03-27T14:45:46+01:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:46 werkstatt go-librespot[14913]: time="2026-03-27T14:45:46+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 14:45:46 werkstatt go-librespot[14913]: time="2026-03-27T14:45:46+01:00" level=trace msg="emitting websocket event: playing" Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:7I3FfuDaoOUiloIuycnE3W","uri":"spotify:track:7I3FfuDaoOUiloIuycnE3W","resume":false,"play_origin":"go-librespot"}} Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: PUSH STATE SPOTIFY Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: {"status":"play","service":"spop","title":"Swoon - Boys Noize Summer Remix","artist":"The Chemical Brothers, Boys Noize","album":"Another World","albumart":"https://i.scdn.co/image/ab67616d00001e026751335513339370f2ee44c4","uri":"spotify:track:0bGJ14HHArD8n3FKqElIik","trackType":"spotify","seek":0,"duration":321,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::servicePushState Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:46 werkstatt volumio[18826]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Swoon - Boys Noize Summer Remix","artist":"The Chemical Brothers, Boys Noize","album":"Another World","albumart":"https://i.scdn.co/image/ab67616d00001e026751335513339370f2ee44c4","uri":"spotify:track:0bGJ14HHArD8n3FKqElIik","trackType":"spotify","seek":0,"duration":321,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 27 14:45:46 werkstatt volumio[18826]: verbose: CURRENT POSITION 3 Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::syncState stateService play Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::syncState currentStatus stop Mar 27 14:45:46 werkstatt go-librespot[14913]: time="2026-03-27T14:45:46+01:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:7I3FfuDaoOUiloIuycnE3W" Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: PUSH STATE SPOTIFY Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: {"status":"play","service":"spop","title":"Swoon - Boys Noize Summer Remix","artist":"The Chemical Brothers, Boys Noize","album":"Another World","albumart":"https://i.scdn.co/image/ab67616d00001e026751335513339370f2ee44c4","uri":"spotify:track:0bGJ14HHArD8n3FKqElIik","trackType":"spotify","seek":0,"duration":321,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::servicePushState Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:46 werkstatt volumio[18826]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Swoon - Boys Noize Summer Remix","artist":"The Chemical Brothers, Boys Noize","album":"Another World","albumart":"https://i.scdn.co/image/ab67616d00001e026751335513339370f2ee44c4","uri":"spotify:track:0bGJ14HHArD8n3FKqElIik","trackType":"spotify","seek":0,"duration":321,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 27 14:45:46 werkstatt volumio[18826]: verbose: CURRENT POSITION 3 Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::syncState stateService play Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::syncState currentStatus play Mar 27 14:45:46 werkstatt volumio[18826]: info: Received an update from plugin. extracting info from payload Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::pushState Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPushState Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::pushState Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPushState Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Mar 27 14:45:46 werkstatt volumio[18826]: info: touch_display: Setting screensaver timeout to 0 seconds. Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::volumioNext Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::next Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::stop Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::stPlaybackTimer Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::updateTrackBlock Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrackBlock Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::pushState Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPushState Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::serviceStop Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 3 Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreCommandRouter::serviceStop Mar 27 14:45:46 werkstatt volumio[18826]: info: Spotify Stop Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: SPOTIFY STOP Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: {"status":"play","position":3,"title":"Swoon - Boys Noize Summer Remix","artist":"The Chemical Brothers","album":"Another World","albumart":"https://i.scdn.co/image/ab67616d0000b2736751335513339370f2ee44c4","uri":"spotify:track:7I3FfuDaoOUiloIuycnE3W","trackType":"spotify","codec":"ogg","seek":0,"duration":321,"samplerate":"160 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":57,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Mar 27 14:45:46 werkstatt volumio[18826]: info: Sending Spotify command to local API: /player/pause Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::play index undefined Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::startPlaybackTimer Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:45:46 werkstatt volumio[18826]: info: [1774619146889] ControllerSpotify::clearAddPlayTrack Mar 27 14:45:46 werkstatt volumio[18826]: info: Sending Spotify command with payload to local API: /player/play Mar 27 14:45:46 werkstatt volumio[18826]: info: CoreStateMachine::updateTrackBlock Mar 27 14:45:46 werkstatt volumio[18826]: info: CorePlayQueue::getTrackBlock Mar 27 14:45:46 werkstatt volumio[18826]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Mar 27 14:45:46 werkstatt go-librespot[14913]: time="2026-03-27T14:45:46+01:00" level=debug msg="pause track at 1070ms" Mar 27 14:45:46 werkstatt volumio[18826]: info: touch_display: Setting screensaver timeout to 120 seconds. Mar 27 14:45:46 werkstatt go-librespot[14913]: time="2026-03-27T14:45:46+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 14:45:47 werkstatt go-librespot[14913]: time="2026-03-27T14:45:47+01:00" level=debug msg="resolved context of track" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:47 werkstatt go-librespot[14913]: time="2026-03-27T14:45:47+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:47 werkstatt go-librespot[14913]: time="2026-03-27T14:45:47+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:47 werkstatt go-librespot[14913]: time="2026-03-27T14:45:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 14:45:47 werkstatt go-librespot[14913]: time="2026-03-27T14:45:47+01:00" level=trace msg="emitting websocket event: will_play" Mar 27 14:45:47 werkstatt volumio[18826]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0AzjHFbG87tJ0JM6hJ2bve","uri":"spotify:track:0AzjHFbG87tJ0JM6hJ2bve","play_origin":"go-librespot"}} Mar 27 14:45:47 werkstatt go-librespot[14913]: time="2026-03-27T14:45: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:0AzjHFbG87tJ0JM6hJ2bve: media is restricted" Mar 27 14:45:47 werkstatt volumio[18826]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 27 14:45:47 werkstatt go-librespot[14913]: time="2026-03-27T14:45:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 14:45:47 werkstatt go-librespot[14913]: time="2026-03-27T14:45:47+01:00" level=trace msg="emitting websocket event: paused" Mar 27 14:45:47 werkstatt volumio[18826]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:0AzjHFbG87tJ0JM6hJ2bve","uri":"spotify:track:0AzjHFbG87tJ0JM6hJ2bve","play_origin":"go-librespot"}} Mar 27 14:45:47 werkstatt volumio[18826]: SPOTIFY: PUSH STATE SPOTIFY Mar 27 14:45:47 werkstatt volumio[18826]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 27 14:45:47 werkstatt volumio[18826]: info: CoreCommandRouter::servicePushState Mar 27 14:45:47 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:45:47 werkstatt volumio[18826]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 27 14:45:47 werkstatt volumio[18826]: verbose: CURRENT POSITION 4 Mar 27 14:45:47 werkstatt volumio[18826]: info: CoreStateMachine::syncState stateService pause Mar 27 14:45:47 werkstatt volumio[18826]: info: CoreStateMachine::syncState currentStatus stop Mar 27 14:45:47 werkstatt volumio[18826]: info: CoreStateMachine::pushState Mar 27 14:45:47 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:45:47 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 14:45:47 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPushState Mar 27 14:45:47 werkstatt volumio[18826]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Mar 27 14:45:51 werkstatt volumio[18826]: info: CoreCommandRouter::volumioPlay Mar 27 14:45:51 werkstatt volumio[18826]: info: CoreStateMachine::play index undefined Mar 27 14:45:51 werkstatt volumio[18826]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 14:45:51 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:45:51 werkstatt volumio[18826]: info: CoreStateMachine::startPlaybackTimer Mar 27 14:45:51 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:45:51 werkstatt volumio[18826]: info: [1774619151352] ControllerSpotify::clearAddPlayTrack Mar 27 14:45:51 werkstatt volumio[18826]: info: Sending Spotify command with payload to local API: /player/play Mar 27 14:45:51 werkstatt go-librespot[14913]: time="2026-03-27T14:45:51+01:00" level=debug msg="resolved context of track" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:51 werkstatt go-librespot[14913]: time="2026-03-27T14:45:51+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:51 werkstatt go-librespot[14913]: time="2026-03-27T14:45:51+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0AzjHFbG87tJ0JM6hJ2bve" Mar 27 14:45:51 werkstatt go-librespot[14913]: time="2026-03-27T14:45:51+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 14:45:51 werkstatt go-librespot[14913]: time="2026-03-27T14:45:51+01:00" level=trace msg="emitting websocket event: will_play" Mar 27 14:45:51 werkstatt volumio[18826]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0AzjHFbG87tJ0JM6hJ2bve","uri":"spotify:track:0AzjHFbG87tJ0JM6hJ2bve","play_origin":"go-librespot"}} Mar 27 14:45:51 werkstatt go-librespot[14913]: time="2026-03-27T14:45:51+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:0AzjHFbG87tJ0JM6hJ2bve: media is restricted" Mar 27 14:45:51 werkstatt volumio[18826]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 27 14:46:02 werkstatt go-librespot[14913]: time="2026-03-27T14:46:02+01:00" level=trace msg="sent dealer ping" Mar 27 14:46:02 werkstatt go-librespot[14913]: time="2026-03-27T14:46:02+01:00" level=trace msg="received dealer pong" Mar 27 14:46:11 werkstatt volumio[18826]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 27 14:46:11 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 27 14:46:11 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 27 14:46:11 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 27 14:46:11 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Mar 27 14:46:12 werkstatt volumio[18826]: info: Received Get System Version Mar 27 14:46:12 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 14:46:12 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Mar 27 14:46:21 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 14:46:21 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 27 14:46:26 werkstatt volumio[18826]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 27 14:46:32 werkstatt go-librespot[14913]: time="2026-03-27T14:46:32+01:00" level=trace msg="sent dealer ping" Mar 27 14:46:32 werkstatt go-librespot[14913]: time="2026-03-27T14:46:32+01:00" level=trace msg="received dealer pong" Mar 27 14:46:35 werkstatt go-librespot[14913]: time="2026-03-27T14:46:35+01:00" level=trace msg="received accesspoint ping" Mar 27 14:46:35 werkstatt go-librespot[14913]: time="2026-03-27T14:46:35+01:00" level=trace msg="received accesspoint pong ack" Mar 27 14:46:38 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:38 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:38 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:38 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:38 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:38 werkstatt sudo[11109]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:38 werkstatt sudo[11109]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:38 werkstatt systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 27 14:46:38 werkstatt systemd[1]: go-librespot-daemon.service: Killing process 14917 (go-librespot) with signal SIGKILL. Mar 27 14:46:38 werkstatt systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 27 14:46:38 werkstatt systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:38 werkstatt systemd[1]: go-librespot-daemon.service: Consumed 24.825s CPU time. Mar 27 14:46:38 werkstatt volumio[18826]: info: Connection to go-librespot Websocket closed Mar 27 14:46:38 werkstatt systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:38 werkstatt go-librespot[11111]: go-librespot daemon starting... Mar 27 14:46:38 werkstatt sudo[11109]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=info msg="running go-librespot 0.7.1" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="app state loaded" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=info msg="zeroconf server listening on port 34247" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="obtained new client token: AAClUAtroCVHvGbXsqkNQ+yj0rD3rsWj1f5fJtUkO2Uw4sPa0WkJuU/ygNktZm1RGQGwgNmN3l6p2tVOnMm9HPjR+2ADwibFtaXPxiDGioOgetuABR6tAy7W3C0lOJiZFUEnxlV4kM4B49UlHI8xR0MvbxZrkfSWwFKuoDn3rwWJD9DOBkwbXtkTIYpZnqAJjPT888R7LplTyPCz0AQmVBDxx0llswrAR5YUNKsN99PC3AanjsE/PjU=" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="completed keyexchange" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="completed challenge" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=info msg="authenticated AP" username="dr**os" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=info msg="authenticated Login5" username="dr**os" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="initializing zeroconf session" username="dr**os" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="dealer connection opened" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=trace msg="starting accesspoint recv loop" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=trace msg="starting dealer recv loop" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=trace msg="received accesspoint ping" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="received connection id: NDgyNjc4MmItMzgx...MkNDQ0FDMTdEMg==" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=trace msg="received accesspoint pong ack" Mar 27 14:46:38 werkstatt go-librespot[11112]: time="2026-03-27T14:46:38+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 27 14:46:39 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:39 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:39 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:39 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:39 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:39 werkstatt sudo[11122]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:39 werkstatt sudo[11122]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:39 werkstatt systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 27 14:46:39 werkstatt systemd[1]: go-librespot-daemon.service: Killing process 11116 (go-librespot) with signal SIGKILL. Mar 27 14:46:39 werkstatt systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 27 14:46:39 werkstatt systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:39 werkstatt systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:39 werkstatt go-librespot[11124]: go-librespot daemon starting... Mar 27 14:46:39 werkstatt sudo[11122]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=info msg="running go-librespot 0.7.1" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="app state loaded" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+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 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+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 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+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 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=info msg="zeroconf server listening on port 45117" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="obtained new client token: AADmBBnPygWmnS3Bf/9VRx+lUcGyqCeilherWbAxgDh2dvbIsIkumS4kSr5h+hrgjM+QOAVf+WAdUgp8PAi6AycpckfSwpmKvzygKgT/JD9EZrOdp4frH6lgGGgH7BRA7Ad8oFvuVoH4XT/DxTL/ZUcItXi+zAdxgbu0etDbuhfbSGR8SZSTezFHS4DA58T8NuNfyT30uuR3pZxCgySOx35kzh/znSoTN+6fk3iwMCrb66hhCvBRmCI=" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="completed keyexchange" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="completed challenge" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=info msg="authenticated AP" username="dr**os" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=info msg="authenticated Login5" username="dr**os" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="initializing zeroconf session" username="dr**os" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="dealer connection opened" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=trace msg="starting accesspoint recv loop" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=trace msg="starting dealer recv loop" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=trace msg="received accesspoint ping" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="received connection id: ZGU4NDgwYjMtZGNl...MDE3NDMzOTE0Mw==" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 27 14:46:39 werkstatt go-librespot[11125]: time="2026-03-27T14:46:39+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 27 14:46:39 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:39 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:39 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:39 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:39 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:39 werkstatt sudo[11135]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:39 werkstatt sudo[11135]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:39 werkstatt systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 27 14:46:39 werkstatt systemd[1]: go-librespot-daemon.service: Killing process 11133 (go-librespot) with signal SIGKILL. Mar 27 14:46:39 werkstatt systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 27 14:46:39 werkstatt systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:39 werkstatt systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:39 werkstatt go-librespot[11137]: go-librespot daemon starting... Mar 27 14:46:39 werkstatt sudo[11135]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:39 werkstatt go-librespot[11138]: time="2026-03-27T14:46:39+01:00" level=info msg="running go-librespot 0.7.1" Mar 27 14:46:39 werkstatt go-librespot[11138]: time="2026-03-27T14:46:39+01:00" level=debug msg="app state loaded" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=info msg="zeroconf server listening on port 35055" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="obtained new client token: AADw74ChWw8xqOFEDoJRvbIyzZ+DyDftgopiYQ2bn+tRpW+8BMKawdc3SO1gfSd0Eua/wik8EWsdfnmgGD+u8MmVZcGd3yUQVanegg65/mPtX1FL6+o3uVLFZGDRGNgkPIBef/A+1TxRHV5+8o5sV7T0Qgf2yfxxcUotLv7sQ5wrnOlmnrTUYa7SXNLDrnP4QGWTS2wDlbmJ82Z6MkV5FKKGoibtraK04dBUWAhSWR7G6BL3HI4y" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="completed keyexchange" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="completed challenge" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=info msg="authenticated AP" username="dr**os" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=info msg="authenticated Login5" username="dr**os" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="initializing zeroconf session" username="dr**os" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="dealer connection opened" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=trace msg="starting accesspoint recv loop" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=trace msg="starting dealer recv loop" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=trace msg="received accesspoint ping" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=debug msg="received connection id: MTlkZTJkYjUtMGEy...QjlBMTUwMzZFNQ==" Mar 27 14:46:40 werkstatt go-librespot[11138]: time="2026-03-27T14:46:40+01:00" level=trace msg="received accesspoint pong ack" Mar 27 14:46:40 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:40 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:40 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:40 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:40 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:40 werkstatt sudo[11148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:40 werkstatt sudo[11148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:40 werkstatt systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 27 14:46:40 werkstatt systemd[1]: go-librespot-daemon.service: Killing process 11143 (go-librespot) with signal SIGKILL. Mar 27 14:46:40 werkstatt systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 27 14:46:40 werkstatt systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:40 werkstatt systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:40 werkstatt go-librespot[11150]: go-librespot daemon starting... Mar 27 14:46:40 werkstatt sudo[11148]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46:40+01:00" level=info msg="running go-librespot 0.7.1" Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46:40+01:00" level=debug msg="app state loaded" Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46:40+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46:40+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46:40+01:00" level=info msg="zeroconf server listening on port 34787" Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46:40+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 27 14:46:40 werkstatt go-librespot[11151]: time="2026-03-27T14:46:40+01:00" level=debug msg="obtained new client token: AAB/EBqRgBaCMyusrlKMnPDVTPnw7p4zCUoyj5MsH/f/dc2FQhHS+9dE8fL/FgjCf40rJaCVjBXEJhkzeNzzn3OUaG5eeQ7GtfvbjsWbF4szeMdktHgqnw6kiS1GkGVqUmt6AV1XqjA+mD7PCixRH0Fy+PWrNpgZpP/97orWf+6sQUvLN6LhZ3ONU/7EsOvZDSqtWLNEU4Uw+AmBmQVGxKWMoVH8tFyW0DNjrS3PqT8nqpdijofFHng=" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="completed keyexchange" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="completed challenge" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=info msg="authenticated AP" username="dr**os" Mar 27 14:46:41 werkstatt volumio[18826]: info: Initializing connection to go-librespot Websocket Mar 27 14:46:41 werkstatt volumio[18826]: info: Connection to go-librespot Websocket established Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="new websocket client" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=info msg="authenticated Login5" username="dr**os" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="initializing zeroconf session" username="dr**os" Mar 27 14:46:41 werkstatt volumio[18826]: info: go-librespot daemon successfully initialized Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="dealer connection opened" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=trace msg="starting accesspoint recv loop" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=trace msg="starting dealer recv loop" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=trace msg="received accesspoint ping" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=debug msg="received connection id: ODFhZTMyYjYtYTY5...OUZCMTAyMkUwRg==" Mar 27 14:46:41 werkstatt go-librespot[11151]: time="2026-03-27T14:46:41+01:00" level=trace msg="received accesspoint pong ack" Mar 27 14:46:41 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:41 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:41 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:41 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:41 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:41 werkstatt sudo[11161]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:41 werkstatt sudo[11161]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:41 werkstatt systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 27 14:46:41 werkstatt systemd[1]: go-librespot-daemon.service: Killing process 11155 (go-librespot) with signal SIGKILL. Mar 27 14:46:41 werkstatt systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 27 14:46:41 werkstatt volumio[18826]: info: Connection to go-librespot Websocket closed Mar 27 14:46:41 werkstatt systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:41 werkstatt systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:41 werkstatt go-librespot[11163]: go-librespot daemon starting... Mar 27 14:46:41 werkstatt sudo[11161]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=info msg="running go-librespot 0.7.1" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=debug msg="app state loaded" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+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 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+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 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+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 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=info msg="zeroconf server listening on port 45633" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=debug msg="obtained new client token: AAAgn2VO6a3q4pKRj4Ul46fzTOQnnQZGwoVrur2b62PXSVlcGnABnOxuvrgDsFBzLqOahZbMYnL73Xondk5cgEAYMGlCT6099TOqXS5v7aIUSFcFlNsjelermvgAhhlbmwK4ivbzo3xEQ8yq4f1VY+fIYjHy4yPYU8dBPx/IgjGfC3RpMT//rWJFoGYC5MyswoQ0XIr2RgF/bHwfZiKSkcCqzOrbrU6ivPgR+5oi0buzYVnRQUkZfKc=" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+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 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=debug msg="completed keyexchange" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=debug msg="completed challenge" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=info msg="authenticated AP" username="dr**os" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=info msg="authenticated Login5" username="dr**os" Mar 27 14:46:41 werkstatt go-librespot[11164]: time="2026-03-27T14:46:41+01:00" level=debug msg="initializing zeroconf session" username="dr**os" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=debug msg="dealer connection opened" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=trace msg="starting accesspoint recv loop" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=trace msg="starting dealer recv loop" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=trace msg="received accesspoint ping" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=debug msg="received connection id: NmFhY2EzOTgtMDJh...QTQ5RDIxQTdERA==" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=trace msg="received accesspoint pong ack" Mar 27 14:46:42 werkstatt go-librespot[11164]: time="2026-03-27T14:46:42+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 27 14:46:42 werkstatt volumio[18826]: info: go-librespot daemon successfully initialized Mar 27 14:46:42 werkstatt volumio[18826]: info: go-librespot daemon successfully initialized Mar 27 14:46:43 werkstatt volumio[18826]: info: go-librespot daemon successfully initialized Mar 27 14:46:44 werkstatt volumio[18826]: info: Getting Spotify volume Mar 27 14:46:44 werkstatt volumio[18826]: info: Spotify volume: 100 Mar 27 14:46:44 werkstatt volumio[18826]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 27 14:46:44 werkstatt volumio[18826]: info: CoreCommandRouter::volumioGetState Mar 27 14:46:44 werkstatt volumio[18826]: info: CorePlayQueue::getTrack 4 Mar 27 14:46:44 werkstatt volumio[18826]: info: Initializing connection to go-librespot Websocket Mar 27 14:46:44 werkstatt volumio[18826]: SPOTIFY: RECEIVED VOLUMIO VOLUME 57 Mar 27 14:46:44 werkstatt volumio[18826]: SPOTIFY: SPOTIFY VOLUME 100 Mar 27 14:46:44 werkstatt volumio[18826]: SPOTIFY: VOLUMIO VOLUME 57 Mar 27 14:46:44 werkstatt volumio[18826]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 27 14:46:44 werkstatt volumio[18826]: info: Setting Spotify Volume from Volumio: 57 Mar 27 14:46:44 werkstatt go-librespot[11164]: time="2026-03-27T14:46:44+01:00" level=debug msg="new websocket client" Mar 27 14:46:44 werkstatt volumio[18826]: info: Connection to go-librespot Websocket established Mar 27 14:46:44 werkstatt volumio[18826]: info: Initializing connection to go-librespot Websocket Mar 27 14:46:44 werkstatt go-librespot[11164]: time="2026-03-27T14:46:44+01:00" level=debug msg="new websocket client" Mar 27 14:46:44 werkstatt volumio[18826]: info: Connection to go-librespot Websocket established Mar 27 14:46:44 werkstatt volumio[18826]: info: go-librespot daemon successfully initialized Mar 27 14:46:44 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:44 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:44 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:44 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:44 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:44 werkstatt sudo[11174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:44 werkstatt sudo[11174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:44 werkstatt systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 27 14:46:44 werkstatt systemd[1]: go-librespot-daemon.service: Killing process 11169 (go-librespot) with signal SIGKILL. Mar 27 14:46:44 werkstatt systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 27 14:46:44 werkstatt volumio[18826]: info: Connection to go-librespot Websocket closed Mar 27 14:46:44 werkstatt systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:44 werkstatt systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 27 14:46:44 werkstatt systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 27 14:46:44 werkstatt volumio[18826]: info: Connection to go-librespot Websocket closed Mar 27 14:46:44 werkstatt systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:44 werkstatt sudo[11174]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:44 werkstatt volumio[18826]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 27 14:46:44 werkstatt volumio[18826]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 27 14:46:44 werkstatt volumio[18826]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 27 14:46:44 werkstatt volumio[18826]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 27 14:46:44 werkstatt volumio[18826]: followed by "systemctl start go-librespot-daemon.service" again. Mar 27 14:46:44 werkstatt volumio[18826]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 27 14:46:44 werkstatt volumio[18826]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 27 14:46:44 werkstatt volumio[18826]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 27 14:46:44 werkstatt volumio[18826]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 27 14:46:44 werkstatt volumio[18826]: followed by "systemctl start go-librespot-daemon.service" again. Mar 27 14:46:45 werkstatt volumio[18826]: info: Initializing connection to go-librespot Websocket Mar 27 14:46:45 werkstatt volumio[18826]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 14:46:45 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:45 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:45 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:45 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:45 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:45 werkstatt sudo[11177]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:45 werkstatt sudo[11177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:45 werkstatt systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 27 14:46:45 werkstatt systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 27 14:46:45 werkstatt systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:45 werkstatt sudo[11177]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:45 werkstatt volumio[18826]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 27 14:46:45 werkstatt volumio[18826]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 27 14:46:45 werkstatt volumio[18826]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 27 14:46:45 werkstatt volumio[18826]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 27 14:46:45 werkstatt volumio[18826]: followed by "systemctl start go-librespot-daemon.service" again. Mar 27 14:46:45 werkstatt volumio[18826]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 27 14:46:45 werkstatt volumio[18826]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 27 14:46:45 werkstatt volumio[18826]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 27 14:46:45 werkstatt volumio[18826]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 27 14:46:45 werkstatt volumio[18826]: followed by "systemctl start go-librespot-daemon.service" again. Mar 27 14:46:45 werkstatt volumio[18826]: SPOTIFY: SETTING SPOTIFY VOLUME 57 Mar 27 14:46:45 werkstatt volumio[18826]: info: Sending Spotify command with payload to local API: /player/volume Mar 27 14:46:45 werkstatt volumio[18826]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 14:46:45 werkstatt volumio[18826]: info: Initializing connection to go-librespot Websocket Mar 27 14:46:45 werkstatt volumio[18826]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 14:46:46 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:46 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:46 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:46 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:46 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:46 werkstatt sudo[11194]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:46 werkstatt sudo[11194]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:46 werkstatt systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 27 14:46:46 werkstatt systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 27 14:46:46 werkstatt systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:46 werkstatt sudo[11194]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:46 werkstatt volumio[18826]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 27 14:46:46 werkstatt volumio[18826]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 27 14:46:46 werkstatt volumio[18826]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 27 14:46:46 werkstatt volumio[18826]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 27 14:46:46 werkstatt volumio[18826]: followed by "systemctl start go-librespot-daemon.service" again. Mar 27 14:46:46 werkstatt volumio[18826]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 27 14:46:46 werkstatt volumio[18826]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 27 14:46:46 werkstatt volumio[18826]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 27 14:46:46 werkstatt volumio[18826]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 27 14:46:46 werkstatt volumio[18826]: followed by "systemctl start go-librespot-daemon.service" again. Mar 27 14:46:46 werkstatt volumio[18826]: info: Initializing connection to go-librespot Websocket Mar 27 14:46:46 werkstatt volumio[18826]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 14:46:46 werkstatt volumio[18826]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 27 14:46:46 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 27 14:46:46 werkstatt volumio[18826]: info: Creating Spotify config file Mar 27 14:46:46 werkstatt volumio[18826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 14:46:46 werkstatt volumio[18826]: info: Spotify config file written Mar 27 14:46:46 werkstatt sudo[11197]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 14:46:46 werkstatt sudo[11197]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:46:46 werkstatt systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 27 14:46:46 werkstatt systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 27 14:46:46 werkstatt systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 27 14:46:46 werkstatt sudo[11197]: pam_unix(sudo:session): session closed for user root Mar 27 14:46:46 werkstatt volumio[18826]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 27 14:46:46 werkstatt volumio[18826]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 27 14:46:46 werkstatt volumio[18826]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 27 14:46:46 werkstatt volumio[18826]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 27 14:46:46 werkstatt volumio[18826]: followed by "systemctl start go-librespot-daemon.service" again. Mar 27 14:46:46 werkstatt volumio[18826]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 27 14:46:46 werkstatt volumio[18826]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 27 14:46:46 werkstatt volumio[18826]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 27 14:46:46 werkstatt volumio[18826]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 27 14:46:46 werkstatt volumio[18826]: followed by "systemctl start go-librespot-daemon.service" again. Mar 27 14:46:47 werkstatt volumio[18826]: info: Getting Spotify volume Mar 27 14:46:47 werkstatt volumio[18826]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 14:46:47 werkstatt volumio[18826]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 14:46:47 werkstatt volumio[18826]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 27 14:46:47 werkstatt volumio[18826]: errno: -111, Mar 27 14:46:47 werkstatt volumio[18826]: code: 'ECONNREFUSED', Mar 27 14:46:47 werkstatt volumio[18826]: syscall: 'connect', Mar 27 14:46:47 werkstatt volumio[18826]: address: '127.0.0.1', Mar 27 14:46:47 werkstatt volumio[18826]: port: 9879, Mar 27 14:46:47 werkstatt volumio[18826]: response: undefined Mar 27 14:46:47 werkstatt volumio[18826]: } Mar 27 14:46:47 werkstatt volumio[18826]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 14:46:47 werkstatt sudo[11216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-27 14:45' Mar 27 14:46:47 werkstatt sudo[11216]: 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"