Feb 09 14:02:09 volumio go-librespot[1653]: time="2026-02-09T14:02:09-08:00" level=trace msg="sent dealer ping" Feb 09 14:02:09 volumio go-librespot[1653]: time="2026-02-09T14:02:09-08:00" level=trace msg="received dealer pong" Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 09 14:02:11 volumio volumio[1357]: info: Getting Alsa Cards List without I2S DAC Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Feb 09 14:02:11 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Feb 09 14:02:14 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:02:14 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:02:29 volumio go-librespot[1653]: time="2026-02-09T14:02:29-08:00" level=info msg="playback was transferred to iPhone" Feb 09 14:02:29 volumio go-librespot[1653]: time="2026-02-09T14:02:29-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 09 14:02:29 volumio go-librespot[1653]: time="2026-02-09T14:02:29-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 09 14:02:29 volumio go-librespot[1653]: time="2026-02-09T14:02:29-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1260" Feb 09 14:02:29 volumio go-librespot[1653]: time="2026-02-09T14:02:29-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 370" Feb 09 14:02:29 volumio go-librespot[1653]: time="2026-02-09T14:02:29-08:00" level=debug msg="put connect state inactive" Feb 09 14:02:29 volumio go-librespot[1653]: time="2026-02-09T14:02:29-08:00" level=trace msg="emitting websocket event: inactive" Feb 09 14:02:29 volumio go-librespot[1653]: time="2026-02-09T14:02:29-08:00" level=trace msg="emitting websocket event: stopped" Feb 09 14:02:29 volumio volumio[1357]: SPOTIFY: received: {"type":"inactive","data":null} Feb 09 14:02:29 volumio volumio[1357]: error: Failed to decode event: inactive Feb 09 14:02:29 volumio volumio[1357]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Feb 09 14:02:29 volumio volumio[1357]: SPOTIFY: PUSH STATE SPOTIFY Feb 09 14:02:29 volumio volumio[1357]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 09 14:02:29 volumio volumio[1357]: info: CoreCommandRouter::servicePushState Feb 09 14:02:29 volumio volumio[1357]: info: CoreStateMachine::pushState Feb 09 14:02:29 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:02:29 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 14:02:29 volumio volumio[1357]: info: CoreCommandRouter::volumioPushState Feb 09 14:02:30 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:02:30 volumio volumio[1357]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 09 14:02:30 volumio volumio[1357]: verbose: CURRENT POSITION 0 Feb 09 14:02:30 volumio volumio[1357]: info: CoreStateMachine::syncState stateService stop Feb 09 14:02:30 volumio volumio[1357]: info: CoreStateMachine::syncState currentStatus stop Feb 09 14:02:30 volumio volumio[1357]: info: CoreStateMachine::pushState Feb 09 14:02:30 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:02:30 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 14:02:30 volumio volumio[1357]: info: CoreCommandRouter::volumioPushState Feb 09 14:02:30 volumio volumio[1357]: info: No code Feb 09 14:02:30 volumio volumio[1357]: info: CoreStateMachine::pushState Feb 09 14:02:30 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:02:30 volumio volumio[1357]: info: CoreCommandRouter::volumioPushState Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="dealer connection closed" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="dealer recv loop stopped" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="obtained new client token: AACvvzsAMAfDRp1zGvAq0Z3Jh5OH1wFLzDWIFqOH7F30QFhErRLqXFROD6t52e2ZHLbO1/lkbuqH5ykjFBnhIDXq+bArjC1NXxavq2HXVmzGOtwKrv7usi2GLA27iyIpN8OEn18T2ISNZmgO4+vwQH4bXsZ+m19NQZ+n2aMWceMQQalBwJHaes+PNuQHtbzv6lGGl8MHdVC+gk/u9631XiLfot8kGsKmRQOARfL9OQ4V9WqU09hEYg==" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="completed keyexchange" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="completed challenge" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=info msg="authenticated AP" username="31************************su" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=info msg="authenticated Login5" username="31************************su" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="restored session after logout" username="31************************su" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="dealer connection opened" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=trace msg="starting accesspoint recv loop" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=trace msg="starting dealer recv loop" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=trace msg="received accesspoint ping" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="received connection id: YjE4OTlkZWUtMjdj...MDNGOUQ2OTRDNg==" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=trace msg="received accesspoint pong ack" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="put connect state because NEW_DEVICE" Feb 09 14:02:30 volumio go-librespot[1653]: time="2026-02-09T14:02:30-08:00" level=debug msg="update volume requested to 65535/65535" Feb 09 14:02:31 volumio go-librespot[1653]: time="2026-02-09T14:02:31-08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 09 14:02:31 volumio go-librespot[1653]: time="2026-02-09T14:02:31-08:00" level=trace msg="emitting websocket event: volume" Feb 09 14:02:31 volumio volumio[1357]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Feb 09 14:02:31 volumio volumio[1357]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Feb 09 14:02:31 volumio volumio[1357]: info: Setting Volumio Volume from Spotify: 100 Feb 09 14:02:31 volumio volumio[1357]: info: VolumeController::SetAlsaVolume100 Feb 09 14:02:31 volumio volumio[1357]: info: CoreStateMachine::pushState Feb 09 14:02:31 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:02:31 volumio volumio[1357]: info: CoreCommandRouter::volumioPushState Feb 09 14:02:47 volumio go-librespot[1653]: time="2026-02-09T14:02:47-08:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1EIdIgV7xVkqjy" Feb 09 14:02:47 volumio go-librespot[1653]: time="2026-02-09T14:02:47-08:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1EIgqlQOL5PM2t" Feb 09 14:02:47 volumio go-librespot[1653]: time="2026-02-09T14:02:47-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Feb 09 14:02:47 volumio go-librespot[1653]: time="2026-02-09T14:02:47-08:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1EIhkeucoxGhUI" Feb 09 14:02:47 volumio go-librespot[1653]: time="2026-02-09T14:02:47-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Feb 09 14:02:47 volumio go-librespot[1653]: time="2026-02-09T14:02:47-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="handling transfer player command from 0ff5d00c86e596776ce471e62a1f8750700876b7" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="resolved context of track" uri="spotify:playlist:4uXBzBg3ELImCTmpyf6yjn" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=trace msg="fetched new page 0 with 59 items (list: 59)" uri="spotify:playlist:4uXBzBg3ELImCTmpyf6yjn" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="loading track (paused: false, position: 4337ms)" uri="spotify:track:6Yy3QRfT2WsUXrdplVdt4h" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=trace msg="emitting websocket event: will_play" Feb 09 14:02:57 volumio volumio[1357]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4uXBzBg3ELImCTmpyf6yjn","uri":"spotify:track:6Yy3QRfT2WsUXrdplVdt4h","play_origin":"playlist/ondemand"}} Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1291" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="selected format OGG_VORBIS_320 (8755527370abbcf3d96cf433ee16cb8a47382968)" uri="spotify:track:6Yy3QRfT2WsUXrdplVdt4h" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="requested aes key for file 8755527370abbcf3d96cf433ee16cb8a47382968, gid: 6Yy3QRfT2WsUXrdplVdt4h" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:6Yy3QRfT2WsUXrdplVdt4h: failed retrieving audio key: failed retrieving aes key with code 1" Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 09 14:02:57 volumio go-librespot[1653]: time="2026-02-09T14:02:57-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 09 14:03:00 volumio go-librespot[1653]: time="2026-02-09T14:03:00-08:00" level=trace msg="sent dealer ping" Feb 09 14:03:00 volumio go-librespot[1653]: time="2026-02-09T14:03:00-08:00" level=trace msg="received dealer pong" Feb 09 14:03:03 volumio volumio[1357]: verbose: New Socket.io Connection to volumio.local from 192.168.108.141 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/26.2 Safari/605.1.15 Engine version: 3 Transport: polling Total Clients: 5 Feb 09 14:03:03 volumio sudo[2404]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 14:03:03 volumio sudo[2404]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:03 volumio sudo[2406]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 14:03:03 volumio sudo[2406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:03 volumio sudo[2404]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:03 volumio sudo[2406]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:03 volumio volumio[1357]: verbose: New Socket.io Connection to 192.168.108.168 from 192.168.108.141 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/26.2 Safari/605.1.15 Engine version: 3 Transport: polling Total Clients: 6 Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:03 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::volumioGetQueue Feb 09 14:03:03 volumio volumio[1357]: info: CoreStateMachine::getQueue Feb 09 14:03:03 volumio volumio[1357]: info: CorePlayQueue::getQueue Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getUpdaterChannel Feb 09 14:03:03 volumio volumio[1357]: info: CALLMETHOD: music_service inputs serialMonitorAction [object Object] Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: inputs , serialMonitorAction Feb 09 14:03:03 volumio volumio[1357]: info: Error : CoreCommandRouter::executeOnPlugin: No method [serialMonitorAction] in plugin inputs Feb 09 14:03:03 volumio volumio[1357]: info: CALLMETHOD: system_controller motivocontrol displaySelection [object Object] Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: motivocontrol , displaySelection Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:03 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 09 14:03:03 volumio volumio[1357]: info: Received Get System Info Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:03:03 volumio volumio[1357]: info: Discovery: Getting this device information Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:03 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:03 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:03 volumio volumio[1357]: info: Listing playlists Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 09 14:03:03 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 09 14:03:04 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:04 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 14:03:05 volumio volumio[1357]: info: Received Get System Info Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:03:05 volumio volumio[1357]: info: Discovery: Getting this device information Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:05 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 14:03:05 volumio volumio[1357]: info: Received Get System Info Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:03:05 volumio volumio[1357]: info: Discovery: Getting this device information Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:05 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:05 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:03:10 volumio volumio[1357]: info: CoreCommandRouter::volumioGetQueue Feb 09 14:03:10 volumio volumio[1357]: info: CoreStateMachine::getQueue Feb 09 14:03:10 volumio volumio[1357]: info: CorePlayQueue::getQueue Feb 09 14:03:13 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 09 14:03:15 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:15 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:16 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 14:03:16 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 09 14:03:21 volumio volumio[1357]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 09 14:03:22 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 09 14:03:22 volumio volumio[1357]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 09 14:03:22 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 09 14:03:22 volumio volumio[1357]: info: Received Get System Version Feb 09 14:03:22 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 14:03:22 volumio volumio[1357]: info: Received Get System Info Feb 09 14:03:22 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:03:22 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:03:22 volumio volumio[1357]: info: Discovery: Getting this device information Feb 09 14:03:22 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:22 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:22 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:03:29 volumio volumio[1357]: info: Received OAUTH Data Feb 09 14:03:29 volumio volumio[1357]: info: Executing Spotify Oauth Login Feb 09 14:03:29 volumio volumio[1357]: info: Saving Spotify Refresh Token Feb 09 14:03:30 volumio volumio[1357]: info: New Spotify access tokenBQAlqhqmIw... Feb 09 14:03:30 volumio volumio[1357]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 09 14:03:30 volumio volumio[1357]: SPOTIFY: User informations: {"country":"US","display_name":"Kevin","email":"fdf9t57f97@privaterelay.appleid.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31cw7z2l4w2oh5ikaondukvf3hsu"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31cw7z2l4w2oh5ikaondukvf3hsu","id":"31cw7z2l4w2oh5ikaondukvf3hsu","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85f4452cbb509835700f5fba6d","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82f4452cbb509835700f5fba6d","width":64}],"product":"premium","type":"user","uri":"spotify:user:31cw7z2l4w2oh5ikaondukvf3hsu"} Feb 09 14:03:30 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:30 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:30 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:30 volumio sudo[2458]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:30 volumio sudo[2458]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:30 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:30 volumio systemd[1]: go-librespot-daemon.service: Killing process 1675 (go-librespot) with signal SIGKILL. Feb 09 14:03:30 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:30 volumio volumio[1357]: info: Connection to go-librespot Websocket closed Feb 09 14:03:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:30 volumio go-librespot[2460]: go-librespot daemon starting... Feb 09 14:03:30 volumio sudo[2458]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=info msg="running go-librespot 0.6.2" Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=debug msg="app state loaded" Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 14:03:30 volumio volumio[1357]: info: New Spotify access tokenBQAF3I6ZP8... Feb 09 14:03:30 volumio volumio[1357]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=info msg="zeroconf server listening on port 38727" Feb 09 14:03:30 volumio volumio[1357]: SPOTIFY: User informations: {"country":"US","display_name":"Kevin","email":"fdf9t57f97@privaterelay.appleid.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31cw7z2l4w2oh5ikaondukvf3hsu"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31cw7z2l4w2oh5ikaondukvf3hsu","id":"31cw7z2l4w2oh5ikaondukvf3hsu","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85f4452cbb509835700f5fba6d","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82f4452cbb509835700f5fba6d","width":64}],"product":"premium","type":"user","uri":"spotify:user:31cw7z2l4w2oh5ikaondukvf3hsu"} Feb 09 14:03:30 volumio volumio[1357]: info: Spotify Successfully logged in Feb 09 14:03:30 volumio volumio[1357]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 14:03:30 volumio volumio[1357]: info: [1770674610813] CoreMusicLibrary::Adding element Spotify Feb 09 14:03:30 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 14:03:30 volumio volumio[1357]: Cannot find translation for source Spotify Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=debug msg="obtained new client token: AADyqtHxOJbNjtQnS6jxBJVmcNGzQuu4cplpANmrov6VFPwLiJV/9nobk6kRkJTtFgX+/3OjmrgEckp0x+AgGrxN1eLSi5/nT7nEmv0YCAr86qZOSjZCFMEh31+pbY9mLK4Tvy/1X4VHKWMrt6YfbglE+pMG47Rci3eU3J9JljWOGtxyTv3+Z5qxnX9SLpDK80IAAPvLBuQoBV7im7gkVqPs5ymWVVThzxvpiiCojqVHBm4Gr1I0fLA6" Feb 09 14:03:30 volumio go-librespot[2461]: time="2026-02-09T14:03:30-08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="completed keyexchange" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="completed challenge" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=info msg="authenticated AP" username="31************************su" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=info msg="authenticated Login5" username="31************************su" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="initializing zeroconf session" username="31************************su" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="dealer connection opened" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=trace msg="starting accesspoint recv loop" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=trace msg="starting dealer recv loop" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=trace msg="received accesspoint ping" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="received connection id: ODhlYzg2ZmYtZDM1...NDhBMDhBRUYxNA==" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=trace msg="received accesspoint pong ack" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="put connect state because NEW_DEVICE" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="update volume requested to 65535/65535" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 09 14:03:31 volumio go-librespot[2461]: time="2026-02-09T14:03:31-08:00" level=trace msg="emitting websocket event: volume" Feb 09 14:03:32 volumio sudo[2471]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 14:03:32 volumio sudo[2471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:32 volumio sudo[2473]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 14:03:32 volumio sudo[2473]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:32 volumio sudo[2471]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:32 volumio sudo[2473]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:32 volumio volumio[1357]: verbose: New Socket.io Connection to 192.168.108.168 from 192.168.108.141 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/26.2 Safari/605.1.15 Engine version: 3 Transport: polling Total Clients: 6 Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:32 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 09 14:03:32 volumio volumio[1357]: info: Received Get System Info Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:03:32 volumio volumio[1357]: info: Discovery: Getting this device information Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:32 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:32 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:32 volumio volumio[1357]: info: Listing playlists Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 09 14:03:32 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 09 14:03:33 volumio volumio[1357]: info: Initializing connection to go-librespot Websocket Feb 09 14:03:33 volumio go-librespot[2461]: time="2026-02-09T14:03:33-08:00" level=debug msg="new websocket client" Feb 09 14:03:33 volumio volumio[1357]: info: Connection to go-librespot Websocket established Feb 09 14:03:33 volumio volumio[1357]: info: go-librespot daemon successfully initialized Feb 09 14:03:33 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 14:03:34 volumio volumio[1357]: info: Received Get System Info Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:03:34 volumio volumio[1357]: info: Discovery: Getting this device information Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:34 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 14:03:34 volumio volumio[1357]: info: Received Get System Info Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:03:34 volumio volumio[1357]: info: Discovery: Getting this device information Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:34 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:34 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:03:36 volumio volumio[1357]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 09 14:03:36 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 09 14:03:36 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:36 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:36 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:36 volumio sudo[2491]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:36 volumio sudo[2491]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:36 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:36 volumio volumio[1357]: info: Connection to go-librespot Websocket closed Feb 09 14:03:36 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:36 volumio go-librespot[2493]: go-librespot daemon starting... Feb 09 14:03:36 volumio sudo[2491]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=info msg="running go-librespot 0.6.2" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="app state loaded" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 14:03:36 volumio volumio[1357]: info: Getting Spotify volume Feb 09 14:03:36 volumio volumio[1357]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 09 14:03:36 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:36 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:36 volumio volumio[1357]: info: Initializing connection to go-librespot Websocket Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="new websocket client" Feb 09 14:03:36 volumio volumio[1357]: info: Connection to go-librespot Websocket established Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=info msg="zeroconf server listening on port 45243" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="obtained new client token: AADdVAG6G7AWjG5mbXcUhiEYMu6PPv5BbTYeJCxtbrvZgf+qBbzrymGXqdJHYE9kzLrJNBhWs6VkHBg4zkpuPploVMtFjTbXXp5LEz2xMxC5q4VDzdAUfxXC2i5MX1zrVCeHHvWz23iRstozKJ297hh9L0DnSjqjN1t1qFeylUqHcopMMowY8nm86GE48mUQH6lrCAYKTfdDUiRfrTQd3dHOdJtBJSzxrl7TdeZ5AfibYg/styeiPz16" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="completed keyexchange" Feb 09 14:03:36 volumio go-librespot[2494]: time="2026-02-09T14:03:36-08:00" level=debug msg="completed challenge" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=info msg="authenticated AP" username="31************************su" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=info msg="authenticated Login5" username="31************************su" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="initializing zeroconf session" username="31************************su" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="dealer connection opened" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=trace msg="starting accesspoint recv loop" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=trace msg="starting dealer recv loop" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=trace msg="received accesspoint ping" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 09 14:03:37 volumio volumio[1357]: info: Spotify volume: 100 Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="received connection id: OGFlYjNhNDUtZmRj...NjQ3Rjc3QjA4QQ==" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=trace msg="received accesspoint pong ack" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="put connect state because NEW_DEVICE" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="update volume requested to 65535/65535" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 09 14:03:37 volumio go-librespot[2494]: time="2026-02-09T14:03:37-08:00" level=trace msg="emitting websocket event: volume" Feb 09 14:03:37 volumio volumio[1357]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Feb 09 14:03:37 volumio volumio[1357]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Feb 09 14:03:38 volumio volumio[1357]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 09 14:03:38 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 09 14:03:38 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:38 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:38 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:38 volumio sudo[2506]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:38 volumio sudo[2506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:38 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:38 volumio systemd[1]: go-librespot-daemon.service: Killing process 2500 (go-librespot) with signal SIGKILL. Feb 09 14:03:38 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:38 volumio volumio[1357]: info: Connection to go-librespot Websocket closed Feb 09 14:03:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:38 volumio go-librespot[2508]: go-librespot daemon starting... Feb 09 14:03:38 volumio sudo[2506]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=info msg="running go-librespot 0.6.2" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=debug msg="app state loaded" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=info msg="zeroconf server listening on port 43111" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=debug msg="obtained new client token: AAAtcpDVmL2p8JPs2ScAV1VGOBxm2O7xWtoT8hKfKp0SPWOaJXDAXW8J8Lkr98PBt57TNg5hSwoLQ10DezT9IQFmAwYmKjLt1d7CMT6iqwezaXPo7KCD5ekecOpKIy05Hu9ru1SWCJeAVMxcgnW7rUoP+EuA5qWfaWEdpUDEDlzIZ87soUUlWdohABdqO8+00HnSZaaicSIJeRA06eITpJlPRV+ZLPAakh7GQ/aPUhmd3FsKfMtOYNyW" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Feb 09 14:03:38 volumio go-librespot[2509]: time="2026-02-09T14:03:38-08:00" level=debug msg="connected to ap-guc3.spotify.com:443" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="completed keyexchange" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="completed challenge" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=info msg="authenticated AP" username="31************************su" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=info msg="authenticated Login5" username="31************************su" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="initializing zeroconf session" username="31************************su" Feb 09 14:03:39 volumio volumio[1357]: info: go-librespot daemon successfully initialized Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="dealer connection opened" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=trace msg="starting accesspoint recv loop" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=trace msg="starting dealer recv loop" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=trace msg="received accesspoint ping" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="received connection id: ZGM3ZTFjOTQtYTNl...QjVDRDE2QTZGQg==" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 09 14:03:39 volumio volumio[1357]: info: Getting Spotify volume Feb 09 14:03:39 volumio volumio[1357]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 09 14:03:39 volumio volumio[1357]: info: CoreCommandRouter::volumioGetState Feb 09 14:03:39 volumio volumio[1357]: info: CorePlayQueue::getTrack 0 Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=trace msg="received accesspoint pong ack" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="put connect state because NEW_DEVICE" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="update volume requested to 65535/65535" Feb 09 14:03:39 volumio volumio[1357]: info: Spotify volume: 100 Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 09 14:03:39 volumio go-librespot[2509]: time="2026-02-09T14:03:39-08:00" level=trace msg="emitting websocket event: volume" Feb 09 14:03:41 volumio volumio[1357]: info: Initializing connection to go-librespot Websocket Feb 09 14:03:41 volumio go-librespot[2509]: time="2026-02-09T14:03:41-08:00" level=debug msg="new websocket client" Feb 09 14:03:41 volumio volumio[1357]: info: Connection to go-librespot Websocket established Feb 09 14:03:41 volumio volumio[1357]: info: go-librespot daemon successfully initialized Feb 09 14:03:42 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 09 14:03:42 volumio volumio[1357]: info: Initializing connection to go-librespot Websocket Feb 09 14:03:42 volumio go-librespot[2509]: time="2026-02-09T14:03:42-08:00" level=debug msg="new websocket client" Feb 09 14:03:42 volumio volumio[1357]: info: Connection to go-librespot Websocket established Feb 09 14:03:42 volumio volumio[1357]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 09 14:03:42 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 09 14:03:42 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:42 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:43 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:43 volumio sudo[2521]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:43 volumio sudo[2521]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:43 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:43 volumio systemd[1]: go-librespot-daemon.service: Killing process 2516 (go-librespot) with signal SIGKILL. Feb 09 14:03:43 volumio volumio[1357]: info: Connection to go-librespot Websocket closed Feb 09 14:03:43 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:43 volumio volumio[1357]: info: Connection to go-librespot Websocket closed Feb 09 14:03:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:43 volumio go-librespot[2523]: go-librespot daemon starting... Feb 09 14:03:43 volumio sudo[2521]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:43 volumio go-librespot[2524]: time="2026-02-09T14:03:43-08:00" level=info msg="running go-librespot 0.6.2" Feb 09 14:03:43 volumio go-librespot[2524]: time="2026-02-09T14:03:43-08:00" level=debug msg="app state loaded" Feb 09 14:03:43 volumio go-librespot[2524]: time="2026-02-09T14:03:43-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 14:03:43 volumio volumio[1357]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 09 14:03:43 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 09 14:03:43 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:43 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:43 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:43 volumio sudo[2533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:43 volumio sudo[2533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:43 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:43 volumio systemd[1]: go-librespot-daemon.service: Killing process 2528 (go-librespot) with signal SIGKILL. Feb 09 14:03:43 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:43 volumio go-librespot[2535]: go-librespot daemon starting... Feb 09 14:03:43 volumio sudo[2533]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:43 volumio go-librespot[2536]: time="2026-02-09T14:03:43-08:00" level=info msg="running go-librespot 0.6.2" Feb 09 14:03:43 volumio go-librespot[2536]: time="2026-02-09T14:03:43-08:00" level=debug msg="app state loaded" Feb 09 14:03:43 volumio go-librespot[2536]: time="2026-02-09T14:03:43-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 14:03:43 volumio volumio[1357]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 09 14:03:43 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 09 14:03:43 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:43 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:43 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:43 volumio sudo[2544]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:43 volumio sudo[2544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:43 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:43 volumio systemd[1]: go-librespot-daemon.service: Killing process 2542 (go-librespot) with signal SIGKILL. Feb 09 14:03:43 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:43 volumio go-librespot[2546]: go-librespot daemon starting... Feb 09 14:03:43 volumio sudo[2544]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:43 volumio go-librespot[2547]: time="2026-02-09T14:03:43-08:00" level=info msg="running go-librespot 0.6.2" Feb 09 14:03:43 volumio go-librespot[2547]: time="2026-02-09T14:03:43-08:00" level=debug msg="app state loaded" Feb 09 14:03:43 volumio go-librespot[2547]: time="2026-02-09T14:03:43-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 14:03:43 volumio volumio[1357]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 09 14:03:43 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 09 14:03:43 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:43 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:43 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:43 volumio sudo[2555]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:43 volumio sudo[2555]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:43 volumio go-librespot[2547]: time="2026-02-09T14:03:43-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 09 14:03:43 volumio go-librespot[2547]: time="2026-02-09T14:03:43-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 09 14:03:43 volumio go-librespot[2547]: time="2026-02-09T14:03:43-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 09 14:03:43 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:43 volumio systemd[1]: go-librespot-daemon.service: Killing process 2552 (go-librespot) with signal SIGKILL. Feb 09 14:03:43 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:43 volumio go-librespot[2557]: go-librespot daemon starting... Feb 09 14:03:43 volumio sudo[2555]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:43 volumio go-librespot[2558]: time="2026-02-09T14:03:43-08:00" level=info msg="running go-librespot 0.6.2" Feb 09 14:03:43 volumio go-librespot[2558]: time="2026-02-09T14:03:43-08:00" level=debug msg="app state loaded" Feb 09 14:03:43 volumio go-librespot[2558]: time="2026-02-09T14:03:43-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 14:03:43 volumio go-librespot[2558]: time="2026-02-09T14:03:43-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 14:03:43 volumio go-librespot[2558]: time="2026-02-09T14:03:43-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 14:03:43 volumio go-librespot[2558]: time="2026-02-09T14:03:43-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 14:03:43 volumio go-librespot[2558]: time="2026-02-09T14:03:43-08:00" level=info msg="zeroconf server listening on port 41723" Feb 09 14:03:43 volumio go-librespot[2558]: time="2026-02-09T14:03:43-08:00" level=debug msg="obtained new client token: AAC42zP9NeOEjkf4GP/chC3wvjDwlUXjvMY/n8ACOsTvPIZ7ifhhZsfL5e8Sxp349f2p0DOAHuPSVeg0CWtNNZM7j75YPpn00D5yUWIFdZmQsyO6w6CAflwFLJ5USeXEs8En9IavmflbP+ebcIQWbyH9ByU7EdPr3iS+esTpKxwQrJHaC+diz51I9LU1RcrZ8K/KCNYrRyrK6QXsaa96Xe6Vv/ieSvcZC+W9ELNeqHC/bTAQVkIPNwk1" Feb 09 14:03:44 volumio go-librespot[2558]: time="2026-02-09T14:03:44-08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 14:03:44 volumio go-librespot[2558]: time="2026-02-09T14:03:44-08:00" level=debug msg="completed keyexchange" Feb 09 14:03:44 volumio go-librespot[2558]: time="2026-02-09T14:03:44-08:00" level=debug msg="completed challenge" Feb 09 14:03:44 volumio volumio[1357]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 09 14:03:44 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 09 14:03:44 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:44 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:44 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:44 volumio sudo[2568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:44 volumio sudo[2568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:44 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:44 volumio systemd[1]: go-librespot-daemon.service: Killing process 2561 (go-librespot) with signal SIGKILL. Feb 09 14:03:44 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:44 volumio go-librespot[2571]: go-librespot daemon starting... Feb 09 14:03:44 volumio sudo[2568]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:44 volumio go-librespot[2572]: time="2026-02-09T14:03:44-08:00" level=info msg="running go-librespot 0.6.2" Feb 09 14:03:44 volumio go-librespot[2572]: time="2026-02-09T14:03:44-08:00" level=debug msg="app state loaded" Feb 09 14:03:44 volumio go-librespot[2572]: time="2026-02-09T14:03:44-08:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 14:03:44 volumio go-librespot[2572]: time="2026-02-09T14:03:44-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 09 14:03:44 volumio go-librespot[2572]: time="2026-02-09T14:03:44-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 09 14:03:44 volumio go-librespot[2572]: time="2026-02-09T14:03:44-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 09 14:03:44 volumio go-librespot[2572]: time="2026-02-09T14:03:44-08:00" level=info msg="zeroconf server listening on port 44939" Feb 09 14:03:44 volumio volumio[1357]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 09 14:03:44 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 09 14:03:44 volumio volumio[1357]: info: Creating Spotify config file Feb 09 14:03:44 volumio volumio[1357]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 14:03:44 volumio volumio[1357]: info: Spotify config file written Feb 09 14:03:44 volumio sudo[2584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 14:03:44 volumio sudo[2584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 14:03:44 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 14:03:44 volumio systemd[1]: go-librespot-daemon.service: Killing process 2576 (go-librespot) with signal SIGKILL. Feb 09 14:03:44 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 14:03:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:44 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Feb 09 14:03:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Feb 09 14:03:44 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Feb 09 14:03:44 volumio sudo[2584]: pam_unix(sudo:session): session closed for user root Feb 09 14:03:44 volumio volumio[1357]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 09 14:03:44 volumio volumio[1357]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 09 14:03:44 volumio volumio[1357]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 09 14:03:44 volumio volumio[1357]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 09 14:03:44 volumio volumio[1357]: followed by "systemctl start go-librespot-daemon.service" again. Feb 09 14:03:44 volumio volumio[1357]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 09 14:03:44 volumio volumio[1357]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 09 14:03:44 volumio volumio[1357]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 09 14:03:44 volumio volumio[1357]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 09 14:03:44 volumio volumio[1357]: followed by "systemctl start go-librespot-daemon.service" again. Feb 09 14:03:44 volumio volumio[1357]: info: Getting Spotify volume Feb 09 14:03:44 volumio volumio[1357]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 14:03:44 volumio volumio[1357]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 09 14:03:44 volumio volumio[1357]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 09 14:03:44 volumio volumio[1357]: errno: -111, Feb 09 14:03:44 volumio volumio[1357]: code: 'ECONNREFUSED', Feb 09 14:03:44 volumio volumio[1357]: syscall: 'connect', Feb 09 14:03:44 volumio volumio[1357]: address: '127.0.0.1', Feb 09 14:03:44 volumio volumio[1357]: port: 9879, Feb 09 14:03:44 volumio volumio[1357]: response: undefined Feb 09 14:03:44 volumio volumio[1357]: } Feb 09 14:03:44 volumio volumio[1357]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 14:03:44 volumio sudo[2600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-09 14:02' Feb 09 14:03:44 volumio sudo[2600]: 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"