Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="handling transfer player command from 8855fca3cc892aec3b1c0fba19e024cf39aecdcc" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EIYoEcoc1o1HZ" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EIYoEcoc1o1HZ" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="loading track (paused: false, position: 2503ms)" uri="spotify:track:7qEHsqek33rTcFNT9PFqLf" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=trace msg="emitting websocket event: will_play" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 310" Feb 21 23:00:00 volumio volumio[14243]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EIYoEcoc1o1HZ","uri":"spotify:track:7qEHsqek33rTcFNT9PFqLf","play_origin":"playlist"}} Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1394" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="selected format OGG_VORBIS_320 (779c585ae171262cedcf79aaf1cad38331cfe0ea)" uri="spotify:track:7qEHsqek33rTcFNT9PFqLf" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="requested aes key for file 779c585ae171262cedcf79aaf1cad38331cfe0ea, gid: 7qEHsqek33rTcFNT9PFqLf" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:7qEHsqek33rTcFNT9PFqLf: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 21 23:00:00 volumio go-librespot[14625]: time="2026-02-21T23:00:00+07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 21 23:00:07 volumio go-librespot[14625]: time="2026-02-21T23:00:07+07:00" level=trace msg="sent dealer ping" Feb 21 23:00:07 volumio go-librespot[14625]: time="2026-02-21T23:00:07+07:00" level=trace msg="received dealer pong" Feb 21 23:00:09 volumio volumio[14243]: verbose: New Socket.io Connection to 192.168.1.140:3000 from 192.168.1.146 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Feb 21 23:00:09 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 21 23:00:09 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 21 23:00:09 volumio volumio[14243]: info: Discovery: Getting this device information Feb 21 23:00:09 volumio volumio[14243]: info: CoreCommandRouter::volumioGetState Feb 21 23:00:09 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:09 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 21 23:00:09 volumio sudo[15273]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 21 23:00:09 volumio sudo[15271]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 21 23:00:09 volumio sudo[15273]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:00:09 volumio sudo[15271]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:00:09 volumio sudo[15273]: pam_unix(sudo:session): session closed for user root Feb 21 23:00:09 volumio sudo[15271]: pam_unix(sudo:session): session closed for user root Feb 21 23:00:10 volumio volumio[14243]: verbose: New Socket.io Connection to 192.168.1.140 from 192.168.1.146 UA: Mozilla/5.0 (Linux; Android 16; SM-F956B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/144.0.7559.132 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Feb 21 23:00:10 volumio sudo[15277]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 21 23:00:10 volumio sudo[15277]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:00:10 volumio sudo[15277]: pam_unix(sudo:session): session closed for user root Feb 21 23:00:10 volumio sudo[15279]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 21 23:00:10 volumio sudo[15279]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:00:10 volumio sudo[15279]: pam_unix(sudo:session): session closed for user root Feb 21 23:00:10 volumio volumio[14243]: verbose: New Socket.io Connection to 192.168.1.140 from 192.168.1.146 UA: Mozilla/5.0 (Linux; Android 16; SM-F956B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/144.0.7559.132 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::volumioGetVisibleSources Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::volumioGetState Feb 21 23:00:10 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 21 23:00:10 volumio volumio[14243]: info: Received Get System Info Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 21 23:00:10 volumio volumio[14243]: info: Discovery: Getting this device information Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::volumioGetState Feb 21 23:00:10 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::volumioGetState Feb 21 23:00:10 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:10 volumio volumio[14243]: info: Listing playlists Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 21 23:00:10 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 21 23:00:11 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 21 23:00:12 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 21 23:00:12 volumio volumio[14243]: info: Received Get System Info Feb 21 23:00:12 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 21 23:00:12 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 21 23:00:12 volumio volumio[14243]: info: Discovery: Getting this device information Feb 21 23:00:12 volumio volumio[14243]: info: CoreCommandRouter::volumioGetState Feb 21 23:00:12 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:12 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 21 23:00:13 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 21 23:00:13 volumio volumio[14243]: info: Received Get System Info Feb 21 23:00:13 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 21 23:00:13 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 21 23:00:13 volumio volumio[14243]: info: Discovery: Getting this device information Feb 21 23:00:13 volumio volumio[14243]: info: CoreCommandRouter::volumioGetState Feb 21 23:00:13 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:13 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 21 23:00:17 volumio volumio[14243]: info: CoreCommandRouter::volumioGetQueue Feb 21 23:00:17 volumio volumio[14243]: info: CoreStateMachine::getQueue Feb 21 23:00:17 volumio volumio[14243]: info: CorePlayQueue::getQueue Feb 21 23:00:20 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 21 23:00:24 volumio volumio[14243]: info: Preload queue cleared Feb 21 23:00:24 volumio volumio[14243]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::ClearQueue Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::stop Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 23:00:24 volumio volumio[14243]: info: CorePlayQueue::clearPlayQueue Feb 21 23:00:24 volumio volumio[14243]: info: CorePlayQueue::saveQueue Feb 21 23:00:24 volumio volumio[14243]: info: CoreCommandRouter::volumioPushQueue Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::addQueueItems Feb 21 23:00:24 volumio volumio[14243]: info: CorePlayQueue::addQueueItems Feb 21 23:00:24 volumio volumio[14243]: info: Preload queue cleared Feb 21 23:00:24 volumio volumio[14243]: info: Adding Item to queue: spotify:album:58itOBI8sKXmkE6Ff9Qzi6 Feb 21 23:00:24 volumio volumio[14243]: info: Exploding uri spotify:album:58itOBI8sKXmkE6Ff9Qzi6 in service spop Feb 21 23:00:24 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:album:58itOBI8sKXmkE6Ff9Qzi6 Feb 21 23:00:24 volumio volumio[14243]: info: CoreCommandRouter::volumioPushQueue Feb 21 23:00:24 volumio volumio[14243]: info: CorePlayQueue::saveQueue Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::updateTrackBlock Feb 21 23:00:24 volumio volumio[14243]: info: CorePlayQueue::getTrackBlock Feb 21 23:00:24 volumio volumio[14243]: info: CoreCommandRouter::volumioPlay Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::play index 0 Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::stop Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::play index undefined Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 23:00:24 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:24 volumio volumio[14243]: info: CoreStateMachine::startPlaybackTimer Feb 21 23:00:24 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:24 volumio volumio[14243]: info: [1771689624738] ControllerSpotify::clearAddPlayTrack Feb 21 23:00:24 volumio volumio[14243]: info: Sending Spotify command with payload to local API: /player/play Feb 21 23:00:24 volumio go-librespot[14625]: time="2026-02-21T23:00:24+07:00" level=debug msg="resolved context of track" uri="spotify:track:1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:24 volumio go-librespot[14625]: time="2026-02-21T23:00:24+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:24 volumio go-librespot[14625]: time="2026-02-21T23:00:24+07:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:24 volumio go-librespot[14625]: time="2026-02-21T23:00:24+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 23:00:24 volumio go-librespot[14625]: time="2026-02-21T23:00:24+07:00" level=trace msg="emitting websocket event: will_play" Feb 21 23:00:24 volumio volumio[14243]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1olh6xBm20qeDOLInB7UAE","uri":"spotify:track:1olh6xBm20qeDOLInB7UAE","play_origin":"go-librespot"}} Feb 21 23:00:24 volumio go-librespot[14625]: time="2026-02-21T23:00:24+07:00" level=debug msg="selected format OGG_VORBIS_320 (9cdd3f47c33b4b2af14581e802a05c4fb3de1bf4)" uri="spotify:track:1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:24 volumio go-librespot[14625]: time="2026-02-21T23:00:24+07:00" level=debug msg="requested aes key for file 9cdd3f47c33b4b2af14581e802a05c4fb3de1bf4, gid: 1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:25 volumio go-librespot[14625]: time="2026-02-21T23:00:25+07:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1olh6xBm20qeDOLInB7UAE: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 23:00:25 volumio volumio[14243]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 23:00:25 volumio go-librespot[14625]: time="2026-02-21T23:00:25+07:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Feb 21 23:00:25 volumio go-librespot[14625]: time="2026-02-21T23:00:25+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 159" Feb 21 23:00:29 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 21 23:00:29 volumio volumio[14243]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 21 23:00:29 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 21 23:00:29 volumio volumio[14243]: info: Received Get System Version Feb 21 23:00:29 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 23:00:29 volumio volumio[14243]: info: Received Get System Info Feb 21 23:00:29 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 21 23:00:29 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 21 23:00:29 volumio volumio[14243]: info: Discovery: Getting this device information Feb 21 23:00:29 volumio volumio[14243]: info: CoreCommandRouter::volumioGetState Feb 21 23:00:29 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:29 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 21 23:00:34 volumio volumio[14243]: info: Preload queue cleared Feb 21 23:00:34 volumio volumio[14243]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::ClearQueue Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::stop Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::clearPlayQueue Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::saveQueue Feb 21 23:00:34 volumio volumio[14243]: info: CoreCommandRouter::volumioPushQueue Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::addQueueItems Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::addQueueItems Feb 21 23:00:34 volumio volumio[14243]: info: Preload queue cleared Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:1olh6xBm20qeDOLInB7UAE Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:1olh6xBm20qeDOLInB7UAE in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:1olh6xBm20qeDOLInB7UAE Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1olh6xBm20qeDOLInB7UAE","service":"spop","name":"Mưa tình cuối đông","artist":"Thùy Dương","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":309,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio volumio[14243]: info: CoreCommandRouter::volumioPushQueue Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::saveQueue Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::updateTrackBlock Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::getTrackBlock Feb 21 23:00:34 volumio volumio[14243]: info: CoreCommandRouter::volumioPlay Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::play index 0 Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::addQueueItems Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::addQueueItems Feb 21 23:00:34 volumio volumio[14243]: info: Preload queue cleared Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:7xRQKQjxZ1ktEznxYQ2IJk Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:7xRQKQjxZ1ktEznxYQ2IJk in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:7xRQKQjxZ1ktEznxYQ2IJk Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:5U866troPAUg6uV95n84bz Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:5U866troPAUg6uV95n84bz in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:5U866troPAUg6uV95n84bz Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:6h170XpcMN6F1HyVp8HZko Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:6h170XpcMN6F1HyVp8HZko in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:6h170XpcMN6F1HyVp8HZko Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:6CgZlO6NZM4dDVwQGVy3s9 Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:6CgZlO6NZM4dDVwQGVy3s9 in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:6CgZlO6NZM4dDVwQGVy3s9 Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:7udDDC4aPgyt3fOD9IFS9z Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:7udDDC4aPgyt3fOD9IFS9z in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:7udDDC4aPgyt3fOD9IFS9z Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:7KTnjFMX7P3Jy7bREmqyHD Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:7KTnjFMX7P3Jy7bREmqyHD in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:7KTnjFMX7P3Jy7bREmqyHD Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:65lfJQNGYdhJlM4fWTPmFf Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:65lfJQNGYdhJlM4fWTPmFf in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:65lfJQNGYdhJlM4fWTPmFf Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:7AZGED2VEAj1cQVZe1iXtE Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:7AZGED2VEAj1cQVZe1iXtE in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:7AZGED2VEAj1cQVZe1iXtE Feb 21 23:00:34 volumio volumio[14243]: info: Adding Item to queue: spotify:track:44RbrouEYpmvh9H5JRIPgj Feb 21 23:00:34 volumio volumio[14243]: info: Exploding uri spotify:track:44RbrouEYpmvh9H5JRIPgj in service spop Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: EXPLODING URI:spotify:track:44RbrouEYpmvh9H5JRIPgj Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::stop Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::play index undefined Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::startPlaybackTimer Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::getTrack 0 Feb 21 23:00:34 volumio volumio[14243]: info: [1771689634505] ControllerSpotify::clearAddPlayTrack Feb 21 23:00:34 volumio volumio[14243]: info: Sending Spotify command with payload to local API: /player/play Feb 21 23:00:34 volumio go-librespot[14625]: time="2026-02-21T23:00:34+07:00" level=debug msg="resolved context of track" uri="spotify:track:1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:34 volumio go-librespot[14625]: time="2026-02-21T23:00:34+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:34 volumio go-librespot[14625]: time="2026-02-21T23:00:34+07:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:34 volumio go-librespot[14625]: time="2026-02-21T23:00:34+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 23:00:34 volumio go-librespot[14625]: time="2026-02-21T23:00:34+07:00" level=trace msg="emitting websocket event: will_play" Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1olh6xBm20qeDOLInB7UAE","uri":"spotify:track:1olh6xBm20qeDOLInB7UAE","play_origin":"go-librespot"}} Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6h170XpcMN6F1HyVp8HZko","service":"spop","name":"Anh chưa thấy mùa xuân","artist":"Thùy Dương","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":329,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6CgZlO6NZM4dDVwQGVy3s9","service":"spop","name":"Mất nhau mùa đông","artist":"Ý Lan","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":253,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:44RbrouEYpmvh9H5JRIPgj","service":"spop","name":"Chuyện tình không suy tư","artist":"Thùy Dương","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":339,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5U866troPAUg6uV95n84bz","service":"spop","name":"Nửa hồn thương đau","artist":"Julie","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":316,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7udDDC4aPgyt3fOD9IFS9z","service":"spop","name":"Trái tim mùa đông","artist":"Thùy Dương","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":369,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7xRQKQjxZ1ktEznxYQ2IJk","service":"spop","name":"Bây giờ tháng mấy","artist":"Tuấn Ngọc","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":342,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio go-librespot[14625]: time="2026-02-21T23:00:34+07:00" level=debug msg="selected format OGG_VORBIS_320 (9cdd3f47c33b4b2af14581e802a05c4fb3de1bf4)" uri="spotify:track:1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:34 volumio go-librespot[14625]: time="2026-02-21T23:00:34+07:00" level=debug msg="requested aes key for file 9cdd3f47c33b4b2af14581e802a05c4fb3de1bf4, gid: 1olh6xBm20qeDOLInB7UAE" Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7AZGED2VEAj1cQVZe1iXtE","service":"spop","name":"Mùa đông sắp đến","artist":"Lâm Thúy Vân","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":379,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:65lfJQNGYdhJlM4fWTPmFf","service":"spop","name":"Ngày vui mùa đông","artist":"Thanh Lan","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":296,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio go-librespot[14625]: time="2026-02-21T23:00:34+07:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1olh6xBm20qeDOLInB7UAE: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 23:00:34 volumio volumio[14243]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 23:00:34 volumio volumio[14243]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7KTnjFMX7P3Jy7bREmqyHD","service":"spop","name":"Con quỳ lạy Chúa - Lời người ngoại đạo","artist":"Thùy Dương","album":"Thùy Dương 2 (Mưa Tình Cuối Đông)","type":"song","duration":248,"albumart":"https://i.scdn.co/image/ab67616d0000b273cffc2f5720710c6d4696a35c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 21 23:00:34 volumio volumio[14243]: info: CoreCommandRouter::volumioPushQueue Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::saveQueue Feb 21 23:00:34 volumio volumio[14243]: info: CoreStateMachine::updateTrackBlock Feb 21 23:00:34 volumio volumio[14243]: info: CorePlayQueue::getTrackBlock Feb 21 23:00:37 volumio go-librespot[14625]: time="2026-02-21T23:00:37+07:00" level=trace msg="sent dealer ping" Feb 21 23:00:37 volumio go-librespot[14625]: time="2026-02-21T23:00:37+07:00" level=trace msg="received dealer pong" Feb 21 23:00:45 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 21 23:00:45 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 21 23:00:49 volumio volumio[14243]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 21 23:01:01 volumio volumio[14243]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 23:01:01 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 23:01:01 volumio volumio[14243]: info: Creating Spotify config file Feb 21 23:01:01 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 23:01:01 volumio volumio[14243]: info: Spotify config file written Feb 21 23:01:01 volumio sudo[15372]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 23:01:01 volumio sudo[15372]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:01:01 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 23:01:01 volumio systemd[1]: go-librespot-daemon.service: Killing process 14641 (go-librespot) with signal SIGKILL. Feb 21 23:01:01 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 23:01:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:01 volumio volumio[14243]: info: Connection to go-librespot Websocket closed Feb 21 23:01:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:01 volumio go-librespot[15374]: go-librespot daemon starting... Feb 21 23:01:01 volumio sudo[15372]: pam_unix(sudo:session): session closed for user root Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=info msg="running go-librespot 0.6.2" Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=debug msg="app state loaded" Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=info msg="zeroconf server listening on port 34863" Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=debug msg="obtained new client token: AACQpoa0E1/qBeOsm79Tq3kJTkyFIOBGzRrDaQfR7UtPsyG+QMwKLqiHt4Wu/5nnaiTZRUgty6pOQuTZ+AIit3130uPNfhJfX5MJmlHLpcoVT/QQQDP8r2aYKaTtDRtscp5UbcKw6cNLIHqChkAkSZWxCAR0Tu4Z5Tbg+NTFmR9FJmw18asm+oLnprUQK0ThKxSLSWt5zuBZZw5mL6HxH8zzGwVZtQfSinZ6zI7fVg1Qhm/SUR3Jq8s=" Feb 21 23:01:01 volumio go-librespot[15375]: time="2026-02-21T23:01:01+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="completed keyexchange" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="completed challenge" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=info msg="authenticated AP" username="31************************wy" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=info msg="authenticated Login5" username="31************************wy" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="initializing zeroconf session" username="31************************wy" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="dealer connection opened" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=trace msg="starting accesspoint recv loop" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=trace msg="starting dealer recv loop" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=trace msg="received accesspoint ping" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=debug msg="received connection id: MDVkOWYwYzAtMWNk...QkFBQThCNUYzQw==" Feb 21 23:01:02 volumio go-librespot[15375]: time="2026-02-21T23:01:02+07:00" level=trace msg="received accesspoint pong ack" Feb 21 23:01:02 volumio volumio[14243]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 23:01:02 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 23:01:02 volumio volumio[14243]: info: Creating Spotify config file Feb 21 23:01:02 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 23:01:02 volumio volumio[14243]: info: Spotify config file written Feb 21 23:01:02 volumio sudo[15385]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 23:01:02 volumio sudo[15385]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:01:02 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 23:01:02 volumio systemd[1]: go-librespot-daemon.service: Killing process 15383 (go-librespot) with signal SIGKILL. Feb 21 23:01:02 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 23:01:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:02 volumio go-librespot[15388]: go-librespot daemon starting... Feb 21 23:01:02 volumio sudo[15385]: pam_unix(sudo:session): session closed for user root Feb 21 23:01:02 volumio go-librespot[15389]: time="2026-02-21T23:01:02+07:00" level=info msg="running go-librespot 0.6.2" Feb 21 23:01:02 volumio go-librespot[15389]: time="2026-02-21T23:01:02+07:00" level=debug msg="app state loaded" Feb 21 23:01:02 volumio go-librespot[15389]: time="2026-02-21T23:01:02+07:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 23:01:02 volumio go-librespot[15389]: time="2026-02-21T23:01:02+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 21 23:01:02 volumio go-librespot[15389]: time="2026-02-21T23:01:02+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 21 23:01:02 volumio go-librespot[15389]: time="2026-02-21T23:01:02+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 21 23:01:03 volumio go-librespot[15389]: time="2026-02-21T23:01:03+07:00" level=info msg="zeroconf server listening on port 37319" Feb 21 23:01:03 volumio go-librespot[15389]: time="2026-02-21T23:01:03+07:00" level=debug msg="obtained new client token: AADp17fPrMk/n2Vm2hs2EhD9X/N2EjPmfWChdAGG3re3WeRYcFKL76VcGwwKy8F4I49kZmPgmnVamAXECL0j6oKETXTVfqW1N8Ag/KhM4Qq/ayzJDcL8o1JM29AXd8M87YgefTHTNe4vNc3iDQ0tWxI/EuIYJxXkDRYhail3uqAcQLnz6q1YV1EbmWCPiZQhdpjFiSyg0Tf5HWiRkiwDzpQYLGX0d5Rvc68zwbL5nCoZISnl0OS9" Feb 21 23:01:03 volumio go-librespot[15389]: time="2026-02-21T23:01:03+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 21 23:01:03 volumio go-librespot[15389]: time="2026-02-21T23:01:03+07:00" level=debug msg="completed keyexchange" Feb 21 23:01:03 volumio go-librespot[15389]: time="2026-02-21T23:01:03+07:00" level=debug msg="completed challenge" Feb 21 23:01:03 volumio go-librespot[15389]: time="2026-02-21T23:01:03+07:00" level=info msg="authenticated AP" username="31************************wy" Feb 21 23:01:03 volumio volumio[14243]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 23:01:03 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 23:01:03 volumio volumio[14243]: info: Creating Spotify config file Feb 21 23:01:03 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 23:01:03 volumio volumio[14243]: info: Spotify config file written Feb 21 23:01:03 volumio sudo[15399]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 23:01:03 volumio sudo[15399]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:01:03 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 23:01:03 volumio systemd[1]: go-librespot-daemon.service: Killing process 15391 (go-librespot) with signal SIGKILL. Feb 21 23:01:03 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 23:01:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:03 volumio go-librespot[15401]: go-librespot daemon starting... Feb 21 23:01:03 volumio sudo[15399]: pam_unix(sudo:session): session closed for user root Feb 21 23:01:03 volumio go-librespot[15402]: time="2026-02-21T23:01:03+07:00" level=info msg="running go-librespot 0.6.2" Feb 21 23:01:03 volumio go-librespot[15402]: time="2026-02-21T23:01:03+07:00" level=debug msg="app state loaded" Feb 21 23:01:03 volumio go-librespot[15402]: time="2026-02-21T23:01:03+07:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 23:01:03 volumio volumio[14243]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 23:01:03 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 23:01:03 volumio volumio[14243]: info: Creating Spotify config file Feb 21 23:01:03 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 23:01:03 volumio volumio[14243]: info: Spotify config file written Feb 21 23:01:03 volumio sudo[15411]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 23:01:03 volumio sudo[15411]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:01:03 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 23:01:03 volumio systemd[1]: go-librespot-daemon.service: Killing process 15405 (go-librespot) with signal SIGKILL. Feb 21 23:01:03 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 23:01:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:03 volumio go-librespot[15413]: go-librespot daemon starting... Feb 21 23:01:03 volumio sudo[15411]: pam_unix(sudo:session): session closed for user root Feb 21 23:01:03 volumio go-librespot[15414]: time="2026-02-21T23:01:03+07:00" level=info msg="running go-librespot 0.6.2" Feb 21 23:01:03 volumio go-librespot[15414]: time="2026-02-21T23:01:03+07:00" level=debug msg="app state loaded" Feb 21 23:01:03 volumio go-librespot[15414]: time="2026-02-21T23:01:03+07:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=info msg="zeroconf server listening on port 32815" Feb 21 23:01:04 volumio volumio[14243]: info: Initializing connection to go-librespot Websocket Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=debug msg="new websocket client" Feb 21 23:01:04 volumio volumio[14243]: info: Connection to go-librespot Websocket established Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=debug msg="obtained new client token: AACTc0PcRVIxRcRhOYl6DfKcLE1pStTH7tD7Nmp0AXGospkL/y72sWsBubB60B3z3PPILLRBDIrClNGsfRQ5fJTCFwjasM7rQIS1TupOzJiZeqmGCn8Wnty+JBxWy+h7uAuDS/spNUUkhQTkIAz9YGC4nIibEUa2AFbBPFRXzP6Hx6PORU8LGGa0oxZZUr8x/LJnd+T3QimS6U+G9R7/DFDPZTJwKTwVhc2xoW0LpdVu5Cinsx8z" Feb 21 23:01:04 volumio volumio[14243]: info: go-librespot daemon successfully initialized Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=debug msg="completed keyexchange" Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=debug msg="completed challenge" Feb 21 23:01:04 volumio go-librespot[15414]: time="2026-02-21T23:01:04+07:00" level=info msg="authenticated AP" username="31************************wy" Feb 21 23:01:04 volumio volumio[14243]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 23:01:04 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 23:01:04 volumio volumio[14243]: info: Creating Spotify config file Feb 21 23:01:04 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 23:01:04 volumio volumio[14243]: info: Spotify config file written Feb 21 23:01:04 volumio sudo[15424]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 23:01:04 volumio sudo[15424]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:01:04 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 23:01:04 volumio systemd[1]: go-librespot-daemon.service: Killing process 15416 (go-librespot) with signal SIGKILL. Feb 21 23:01:04 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 23:01:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:04 volumio volumio[14243]: info: Connection to go-librespot Websocket closed Feb 21 23:01:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:04 volumio go-librespot[15426]: go-librespot daemon starting... Feb 21 23:01:04 volumio sudo[15424]: pam_unix(sudo:session): session closed for user root Feb 21 23:01:04 volumio go-librespot[15427]: time="2026-02-21T23:01:04+07:00" level=info msg="running go-librespot 0.6.2" Feb 21 23:01:04 volumio go-librespot[15427]: time="2026-02-21T23:01:04+07:00" level=debug msg="app state loaded" Feb 21 23:01:04 volumio go-librespot[15427]: time="2026-02-21T23:01:04+07:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 23:01:04 volumio volumio[14243]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 23:01:04 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 23:01:04 volumio volumio[14243]: info: Creating Spotify config file Feb 21 23:01:04 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 23:01:04 volumio volumio[14243]: info: Spotify config file written Feb 21 23:01:04 volumio sudo[15436]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 23:01:04 volumio sudo[15436]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:01:04 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 23:01:04 volumio systemd[1]: go-librespot-daemon.service: Killing process 15431 (go-librespot) with signal SIGKILL. Feb 21 23:01:04 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 23:01:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:04 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Feb 21 23:01:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Feb 21 23:01:04 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:04 volumio sudo[15436]: pam_unix(sudo:session): session closed for user root Feb 21 23:01:04 volumio volumio[14243]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 21 23:01:04 volumio volumio[14243]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 21 23:01:04 volumio volumio[14243]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 21 23:01:04 volumio volumio[14243]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 21 23:01:04 volumio volumio[14243]: followed by "systemctl start go-librespot-daemon.service" again. Feb 21 23:01:04 volumio volumio[14243]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 21 23:01:04 volumio volumio[14243]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 21 23:01:04 volumio volumio[14243]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 21 23:01:04 volumio volumio[14243]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 21 23:01:04 volumio volumio[14243]: followed by "systemctl start go-librespot-daemon.service" again. Feb 21 23:01:05 volumio volumio[14243]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 23:01:05 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 23:01:05 volumio volumio[14243]: info: Creating Spotify config file Feb 21 23:01:05 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 23:01:05 volumio volumio[14243]: info: Spotify config file written Feb 21 23:01:05 volumio volumio[14243]: info: go-librespot daemon successfully initialized Feb 21 23:01:05 volumio sudo[15439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 23:01:05 volumio sudo[15439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:01:05 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Feb 21 23:01:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Feb 21 23:01:05 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:05 volumio sudo[15439]: pam_unix(sudo:session): session closed for user root Feb 21 23:01:05 volumio volumio[14243]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 21 23:01:05 volumio volumio[14243]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 21 23:01:05 volumio volumio[14243]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 21 23:01:05 volumio volumio[14243]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 21 23:01:05 volumio volumio[14243]: followed by "systemctl start go-librespot-daemon.service" again. Feb 21 23:01:05 volumio volumio[14243]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 21 23:01:05 volumio volumio[14243]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 21 23:01:05 volumio volumio[14243]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 21 23:01:05 volumio volumio[14243]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 21 23:01:05 volumio volumio[14243]: followed by "systemctl start go-librespot-daemon.service" again. Feb 21 23:01:05 volumio volumio[14243]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 23:01:05 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 23:01:05 volumio volumio[14243]: info: Creating Spotify config file Feb 21 23:01:05 volumio volumio[14243]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 23:01:05 volumio volumio[14243]: info: Spotify config file written Feb 21 23:01:05 volumio sudo[15442]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 23:01:05 volumio sudo[15442]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 23:01:05 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Feb 21 23:01:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Feb 21 23:01:05 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Feb 21 23:01:05 volumio sudo[15442]: pam_unix(sudo:session): session closed for user root Feb 21 23:01:05 volumio volumio[14243]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 21 23:01:05 volumio volumio[14243]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 21 23:01:05 volumio volumio[14243]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 21 23:01:05 volumio volumio[14243]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 21 23:01:05 volumio volumio[14243]: followed by "systemctl start go-librespot-daemon.service" again. Feb 21 23:01:05 volumio volumio[14243]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 21 23:01:05 volumio volumio[14243]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 21 23:01:05 volumio volumio[14243]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 21 23:01:05 volumio volumio[14243]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 21 23:01:05 volumio volumio[14243]: followed by "systemctl start go-librespot-daemon.service" again. Feb 21 23:01:06 volumio volumio[14243]: info: go-librespot daemon successfully initialized Feb 21 23:01:06 volumio volumio[14243]: info: go-librespot daemon successfully initialized Feb 21 23:01:07 volumio volumio[14243]: info: Getting Spotify volume Feb 21 23:01:07 volumio volumio[14243]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 23:01:07 volumio volumio[14243]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 21 23:01:07 volumio volumio[14243]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 21 23:01:07 volumio volumio[14243]: errno: -111, Feb 21 23:01:07 volumio volumio[14243]: code: 'ECONNREFUSED', Feb 21 23:01:07 volumio volumio[14243]: syscall: 'connect', Feb 21 23:01:07 volumio volumio[14243]: address: '127.0.0.1', Feb 21 23:01:07 volumio volumio[14243]: port: 9879, Feb 21 23:01:07 volumio volumio[14243]: response: undefined Feb 21 23:01:07 volumio volumio[14243]: } Feb 21 23:01:07 volumio volumio[14243]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 23:01:08 volumio sudo[15472]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-21 23:00' Feb 21 23:01:08 volumio sudo[15472]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"