Mar 04 14:01:21 volumio1 go-librespot[8838]: time="2026-03-04T14:01:21+02:00" level=trace msg="sent dealer ping" Mar 04 14:01:21 volumio1 go-librespot[8838]: time="2026-03-04T14:01:21+02:00" level=trace msg="received dealer pong" Mar 04 14:01:51 volumio1 go-librespot[8838]: time="2026-03-04T14:01:51+02:00" level=trace msg="sent dealer ping" Mar 04 14:01:51 volumio1 go-librespot[8838]: time="2026-03-04T14:01:51+02:00" level=trace msg="received dealer pong" Mar 04 14:02:00 volumio1 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Mar 04 14:02:01 volumio1 systemd[1]: setdatetime-helper.service: Deactivated successfully. Mar 04 14:02:01 volumio1 systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Mar 04 14:02:15 volumio1 volumio[1184]: info: CoreCommandRouter::volumioGetState Mar 04 14:02:15 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:19 volumio1 volumio[1184]: info: CoreCommandRouter::volumioPlay Mar 04 14:02:19 volumio1 volumio[1184]: info: CoreStateMachine::play index undefined Mar 04 14:02:19 volumio1 volumio[1184]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 04 14:02:19 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:19 volumio1 volumio[1184]: info: CoreStateMachine::startPlaybackTimer Mar 04 14:02:19 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:19 volumio1 volumio[1184]: info: [1772625739567] ControllerSpotify::clearAddPlayTrack Mar 04 14:02:19 volumio1 volumio[1184]: info: Sending Spotify command with payload to local API: /player/play Mar 04 14:02:19 volumio1 go-librespot[8838]: time="2026-03-04T14:02:19+02:00" level=debug msg="resolved context of track" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:19 volumio1 go-librespot[8838]: time="2026-03-04T14:02:19+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:19 volumio1 go-librespot[8838]: time="2026-03-04T14:02:19+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:19 volumio1 go-librespot[8838]: time="2026-03-04T14:02:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 04 14:02:19 volumio1 go-librespot[8838]: time="2026-03-04T14:02:19+02:00" level=trace msg="emitting websocket event: will_play" Mar 04 14:02:19 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:19 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:19 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreCommandRouter::volumioPlay Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::play index undefined Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 04 14:02:20 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::startPlaybackTimer Mar 04 14:02:20 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:20 volumio1 volumio[1184]: info: [1772625740032] ControllerSpotify::clearAddPlayTrack Mar 04 14:02:20 volumio1 volumio[1184]: info: Sending Spotify command with payload to local API: /player/play Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="selected format OGG_VORBIS_320 (ac9ff2e573d4cfe385a94fffc13900e6179ee5b0)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="requested aes key for file ac9ff2e573d4cfe385a94fffc13900e6179ee5b0, gid: 1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreCommandRouter::volumioPlay Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::play index undefined Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 04 14:02:20 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::startPlaybackTimer Mar 04 14:02:20 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:20 volumio1 volumio[1184]: info: [1772625740237] ControllerSpotify::clearAddPlayTrack Mar 04 14:02:20 volumio1 volumio[1184]: info: Sending Spotify command with payload to local API: /player/play Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1Nerc47lbCxi2IeXDsLnEN: failed retrieving audio key: failed retrieving aes key with code 1" Mar 04 14:02:20 volumio1 volumio[1184]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="resolved context of track" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreCommandRouter::volumioPlay Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::play index undefined Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 04 14:02:20 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::startPlaybackTimer Mar 04 14:02:20 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:20 volumio1 volumio[1184]: info: [1772625740424] ControllerSpotify::clearAddPlayTrack Mar 04 14:02:20 volumio1 volumio[1184]: info: Sending Spotify command with payload to local API: /player/play Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=trace msg="emitting websocket event: will_play" Mar 04 14:02:20 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:20 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:20 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreCommandRouter::volumioPlay Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::play index undefined Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 04 14:02:20 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:20 volumio1 volumio[1184]: info: CoreStateMachine::startPlaybackTimer Mar 04 14:02:20 volumio1 volumio[1184]: info: CorePlayQueue::getTrack 4 Mar 04 14:02:20 volumio1 volumio[1184]: info: [1772625740592] ControllerSpotify::clearAddPlayTrack Mar 04 14:02:20 volumio1 volumio[1184]: info: Sending Spotify command with payload to local API: /player/play Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="selected format OGG_VORBIS_320 (ac9ff2e573d4cfe385a94fffc13900e6179ee5b0)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="requested aes key for file ac9ff2e573d4cfe385a94fffc13900e6179ee5b0, gid: 1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1Nerc47lbCxi2IeXDsLnEN: failed retrieving audio key: failed retrieving aes key with code 1" Mar 04 14:02:20 volumio1 volumio[1184]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="resolved context of track" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 04 14:02:20 volumio1 go-librespot[8838]: time="2026-03-04T14:02:20+02:00" level=trace msg="emitting websocket event: will_play" Mar 04 14:02:20 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:20 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:20 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="selected format OGG_VORBIS_320 (ac9ff2e573d4cfe385a94fffc13900e6179ee5b0)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="requested aes key for file ac9ff2e573d4cfe385a94fffc13900e6179ee5b0, gid: 1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=trace msg="received accesspoint ping" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1Nerc47lbCxi2IeXDsLnEN: failed retrieving audio key: failed retrieving aes key with code 1" Mar 04 14:02:21 volumio1 volumio[1184]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="resolved context of track" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=trace msg="received accesspoint pong ack" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=trace msg="emitting websocket event: will_play" Mar 04 14:02:21 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:21 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:21 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="selected format OGG_VORBIS_320 (ac9ff2e573d4cfe385a94fffc13900e6179ee5b0)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="requested aes key for file ac9ff2e573d4cfe385a94fffc13900e6179ee5b0, gid: 1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1Nerc47lbCxi2IeXDsLnEN: failed retrieving audio key: failed retrieving aes key with code 1" Mar 04 14:02:21 volumio1 volumio[1184]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=trace msg="sent dealer ping" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="resolved context of track" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:21 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:22 volumio1 go-librespot[8838]: time="2026-03-04T14:02:21+02:00" level=trace msg="received dealer pong" Mar 04 14:02:22 volumio1 go-librespot[8838]: time="2026-03-04T14:02:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 04 14:02:22 volumio1 go-librespot[8838]: time="2026-03-04T14:02:22+02:00" level=trace msg="emitting websocket event: will_play" Mar 04 14:02:22 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:22 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:22 volumio1 volumio[1184]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","uri":"spotify:track:1Nerc47lbCxi2IeXDsLnEN","play_origin":"go-librespot"}} Mar 04 14:02:22 volumio1 go-librespot[8838]: time="2026-03-04T14:02:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (ac9ff2e573d4cfe385a94fffc13900e6179ee5b0)" uri="spotify:track:1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:22 volumio1 go-librespot[8838]: time="2026-03-04T14:02:22+02:00" level=debug msg="requested aes key for file ac9ff2e573d4cfe385a94fffc13900e6179ee5b0, gid: 1Nerc47lbCxi2IeXDsLnEN" Mar 04 14:02:22 volumio1 go-librespot[8838]: time="2026-03-04T14:02:22+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1Nerc47lbCxi2IeXDsLnEN: failed retrieving audio key: failed retrieving aes key with code 1" Mar 04 14:02:22 volumio1 volumio[1184]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Mar 04 14:02:26 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 04 14:02:26 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 04 14:02:33 volumio1 volumio[1184]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 04 14:02:44 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:44 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:44 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:44 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:44 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:44 volumio1 sudo[10245]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:44 volumio1 sudo[10245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:44 volumio1 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 04 14:02:44 volumio1 volumio[1184]: info: Connection to go-librespot Websocket closed Mar 04 14:02:44 volumio1 volumio[1184]: info: Connection to go-librespot Websocket closed Mar 04 14:02:44 volumio1 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 04 14:02:44 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:44 volumio1 volumio[1184]: info: Connection to go-librespot Websocket closed Mar 04 14:02:44 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:44 volumio1 sudo[10245]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:44 volumio1 go-librespot[10247]: go-librespot daemon starting... Mar 04 14:02:44 volumio1 go-librespot[10248]: time="2026-03-04T14:02:44+02:00" level=info msg="running go-librespot 0.7.1" Mar 04 14:02:44 volumio1 go-librespot[10248]: time="2026-03-04T14:02:44+02:00" level=debug msg="app state loaded" Mar 04 14:02:44 volumio1 go-librespot[10248]: time="2026-03-04T14:02:44+02:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 14:02:45 volumio1 go-librespot[10248]: time="2026-03-04T14:02:45+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 04 14:02:45 volumio1 go-librespot[10248]: time="2026-03-04T14:02:45+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 04 14:02:45 volumio1 go-librespot[10248]: time="2026-03-04T14:02:45+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 04 14:02:45 volumio1 go-librespot[10248]: time="2026-03-04T14:02:45+02:00" level=info msg="zeroconf server listening on port 44191" Mar 04 14:02:45 volumio1 go-librespot[10248]: time="2026-03-04T14:02:45+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 04 14:02:45 volumio1 go-librespot[10248]: time="2026-03-04T14:02:45+02:00" level=debug msg="obtained new client token: AAAh5Y77BX5Bl4/5x0O6b0/zD5Smqz82r6YHaYLhWzdDmENwD5o/lNsgHN0c02Wl7Mrg/KREZhLYwv5onKGjsnE+d1QsoO3lc5l63CHxyriqscWSqkBOSTAhYBdJBCv/3Wm5uY7F14vhscOFM8YiEagPBBbR2a9aKr/msckgoT20Ug1cedw5RUUic7UYYaXZwiew2dArfOA7vZbdMRZMagosdmvpbtlDGDtxxSmIChq6Fv4HwBkl" Mar 04 14:02:45 volumio1 go-librespot[10248]: time="2026-03-04T14:02:45+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="completed keyexchange" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="completed challenge" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=info msg="authenticated AP" username="31************************l4" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=info msg="authenticated Login5" username="31************************l4" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="initializing zeroconf session" username="31************************l4" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="dealer connection opened" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=trace msg="starting accesspoint recv loop" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=trace msg="starting dealer recv loop" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=trace msg="received accesspoint ping" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=debug msg="received connection id: MTEwMmEzNmItM2Rj...NjdCRUFDQkQyQg==" Mar 04 14:02:46 volumio1 go-librespot[10248]: time="2026-03-04T14:02:46+02:00" level=trace msg="received accesspoint pong ack" Mar 04 14:02:47 volumio1 go-librespot[10248]: time="2026-03-04T14:02:47+02:00" level=debug msg="put connect state because NEW_DEVICE" Mar 04 14:02:47 volumio1 volumio[1184]: info: Initializing connection to go-librespot Websocket Mar 04 14:02:47 volumio1 volumio[1184]: info: Connection to go-librespot Websocket established Mar 04 14:02:47 volumio1 go-librespot[10248]: time="2026-03-04T14:02:47+02:00" level=debug msg="new websocket client" Mar 04 14:02:47 volumio1 volumio[1184]: info: go-librespot daemon successfully initialized Mar 04 14:02:47 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:47 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:47 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:47 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:47 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:47 volumio1 sudo[10260]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:47 volumio1 sudo[10260]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:48 volumio1 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 04 14:02:48 volumio1 systemd[1]: go-librespot-daemon.service: Killing process 10255 (go-librespot) with signal SIGKILL. Mar 04 14:02:48 volumio1 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 04 14:02:48 volumio1 volumio[1184]: info: Connection to go-librespot Websocket closed Mar 04 14:02:48 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:48 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:48 volumio1 sudo[10260]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:48 volumio1 go-librespot[10262]: go-librespot daemon starting... Mar 04 14:02:48 volumio1 go-librespot[10263]: time="2026-03-04T14:02:48+02:00" level=info msg="running go-librespot 0.7.1" Mar 04 14:02:48 volumio1 go-librespot[10263]: time="2026-03-04T14:02:48+02:00" level=debug msg="app state loaded" Mar 04 14:02:48 volumio1 go-librespot[10263]: time="2026-03-04T14:02:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 14:02:48 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:48 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:48 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:48 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:48 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:48 volumio1 sudo[10272]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:48 volumio1 sudo[10272]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:48 volumio1 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 04 14:02:48 volumio1 systemd[1]: go-librespot-daemon.service: Killing process 10271 (go-librespot) with signal SIGKILL. Mar 04 14:02:48 volumio1 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 04 14:02:48 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:48 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:48 volumio1 sudo[10272]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:48 volumio1 go-librespot[10274]: go-librespot daemon starting... Mar 04 14:02:48 volumio1 go-librespot[10275]: time="2026-03-04T14:02:48+02:00" level=info msg="running go-librespot 0.7.1" Mar 04 14:02:48 volumio1 go-librespot[10275]: time="2026-03-04T14:02:48+02:00" level=debug msg="app state loaded" Mar 04 14:02:48 volumio1 go-librespot[10275]: time="2026-03-04T14:02:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 14:02:48 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:48 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:48 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:48 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:48 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:48 volumio1 sudo[10285]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:48 volumio1 sudo[10285]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:48 volumio1 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 04 14:02:48 volumio1 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 04 14:02:48 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:48 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:48 volumio1 go-librespot[10287]: go-librespot daemon starting... Mar 04 14:02:48 volumio1 sudo[10285]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:48 volumio1 go-librespot[10288]: time="2026-03-04T14:02:48+02:00" level=info msg="running go-librespot 0.7.1" Mar 04 14:02:48 volumio1 go-librespot[10288]: time="2026-03-04T14:02:48+02:00" level=debug msg="app state loaded" Mar 04 14:02:48 volumio1 go-librespot[10288]: time="2026-03-04T14:02:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 14:02:48 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:48 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:48 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:48 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:48 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:48 volumio1 sudo[10296]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:48 volumio1 sudo[10296]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:48 volumio1 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 04 14:02:48 volumio1 systemd[1]: go-librespot-daemon.service: Killing process 10292 (go-librespot) with signal SIGKILL. Mar 04 14:02:48 volumio1 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 04 14:02:48 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:48 volumio1 sudo[10296]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:48 volumio1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:48 volumio1 go-librespot[10298]: go-librespot daemon starting... Mar 04 14:02:48 volumio1 go-librespot[10299]: time="2026-03-04T14:02:48+02:00" level=info msg="running go-librespot 0.7.1" Mar 04 14:02:48 volumio1 go-librespot[10299]: time="2026-03-04T14:02:48+02:00" level=debug msg="app state loaded" Mar 04 14:02:48 volumio1 go-librespot[10299]: time="2026-03-04T14:02:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 14:02:49 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:49 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:49 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:49 volumio1 sudo[10307]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 sudo[10307]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:49 volumio1 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Killing process 10308 (go-librespot) with signal SIGKILL. Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 04 14:02:49 volumio1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 04 14:02:49 volumio1 systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:49 volumio1 sudo[10307]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:49 volumio1 volumio[1184]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:49 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:49 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:49 volumio1 sudo[10311]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 sudo[10311]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 04 14:02:49 volumio1 systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:49 volumio1 sudo[10311]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:49 volumio1 volumio[1184]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:49 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:49 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:49 volumio1 sudo[10314]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 sudo[10314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 04 14:02:49 volumio1 systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:49 volumio1 sudo[10314]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:49 volumio1 volumio[1184]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:49 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:49 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:49 volumio1 sudo[10318]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 sudo[10318]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 04 14:02:49 volumio1 systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:49 volumio1 sudo[10318]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:49 volumio1 volumio[1184]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:49 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:49 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:49 volumio1 sudo[10321]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 sudo[10321]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 04 14:02:49 volumio1 systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:49 volumio1 sudo[10321]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:49 volumio1 volumio[1184]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 04 14:02:49 volumio1 volumio[1184]: info: Creating Spotify config file Mar 04 14:02:49 volumio1 volumio[1184]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 04 14:02:49 volumio1 volumio[1184]: info: Spotify config file written Mar 04 14:02:49 volumio1 sudo[10324]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 sudo[10324]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 04 14:02:49 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 04 14:02:49 volumio1 systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 04 14:02:49 volumio1 sudo[10324]: pam_unix(sudo:session): session closed for user root Mar 04 14:02:49 volumio1 volumio[1184]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:49 volumio1 volumio[1184]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 04 14:02:49 volumio1 volumio[1184]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 04 14:02:49 volumio1 volumio[1184]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 04 14:02:49 volumio1 volumio[1184]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 04 14:02:49 volumio1 volumio[1184]: followed by "systemctl start go-librespot-daemon.service" again. Mar 04 14:02:50 volumio1 volumio[1184]: info: Getting Spotify volume Mar 04 14:02:50 volumio1 volumio[1184]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 04 14:02:50 volumio1 volumio[1184]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 14:02:50 volumio1 volumio[1184]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 04 14:02:50 volumio1 volumio[1184]: errno: -111, Mar 04 14:02:50 volumio1 volumio[1184]: code: 'ECONNREFUSED', Mar 04 14:02:50 volumio1 volumio[1184]: syscall: 'connect', Mar 04 14:02:50 volumio1 volumio[1184]: address: '127.0.0.1', Mar 04 14:02:50 volumio1 volumio[1184]: port: 9879, Mar 04 14:02:50 volumio1 volumio[1184]: response: undefined Mar 04 14:02:50 volumio1 volumio[1184]: } Mar 04 14:02:50 volumio1 volumio[1184]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 04 14:02:51 volumio1 sudo[10341]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-04 14:01' Mar 04 14:02:51 volumio1 sudo[10341]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:31:57 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6759e875c98b942866984e844891d6c1"