-- Logs begin at Thu 2019-02-14 17:11:59 +07, end at Sat 2025-09-06 10:40:32 +07. -- Sep 06 10:39:00 music go-librespot[4791]: time="2025-09-06T10:39:00+07:00" level=trace msg="sent dealer ping" Sep 06 10:39:00 music go-librespot[4791]: time="2025-09-06T10:39:00+07:00" level=trace msg="received dealer pong" Sep 06 10:39:07 music volumio[1010]: info: CoreCommandRouter::volumioPlay Sep 06 10:39:07 music volumio[1010]: info: CoreStateMachine::play index undefined Sep 06 10:39:07 music volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 06 10:39:07 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:07 music volumio[1010]: info: CoreStateMachine::startPlaybackTimer Sep 06 10:39:07 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:07 music volumio[1010]: info: [1757129947559] ControllerSpotify::clearAddPlayTrack Sep 06 10:39:07 music volumio[1010]: info: Sending Spotify command with payload to local API: /player/play Sep 06 10:39:07 music go-librespot[4791]: time="2025-09-06T10:39:07+07:00" level=debug msg="resolved context of track" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:07 music go-librespot[4791]: time="2025-09-06T10:39:07+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:07 music go-librespot[4791]: time="2025-09-06T10:39:07+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:07 music go-librespot[4791]: time="2025-09-06T10:39:07+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 10:39:07 music go-librespot[4791]: time="2025-09-06T10:39:07+07:00" level=trace msg="emitting websocket event: will_play" Sep 06 10:39:07 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:39:07 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:39:07 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:39:07 music go-librespot[4791]: time="2025-09-06T10:39:07+07:00" level=debug msg="selected format OGG_VORBIS_320 (364f83cb061295a0aac2c54835362197e39cdd10)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:07 music go-librespot[4791]: time="2025-09-06T10:39:07+07:00" level=debug msg="requested aes key for file 364f83cb061295a0aac2c54835362197e39cdd10, gid: 5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:07 music go-librespot[4791]: time="2025-09-06T10:39:07+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:5zXCoF69UxPNLrpar8Rk7e: failed retrieving audio key: failed retrieving aes key with code 1" Sep 06 10:39:07 music volumio[1010]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 06 10:39:30 music go-librespot[4791]: time="2025-09-06T10:39:30+07:00" level=trace msg="sent dealer ping" Sep 06 10:39:30 music ntpd[828]: Soliciting pool server 115.165.161.155 Sep 06 10:39:30 music go-librespot[4791]: time="2025-09-06T10:39:30+07:00" level=trace msg="received dealer pong" Sep 06 10:39:33 music ntpd[828]: Soliciting pool server 103.184.124.254 Sep 06 10:39:34 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:39:34 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:39:34 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:39:34 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:34 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:34 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:39:34 music ntpd[828]: Soliciting pool server 103.70.115.65 Sep 06 10:39:36 music ntpd[828]: Soliciting pool server 103.184.124.254 Sep 06 10:39:37 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 7 Sep 06 10:39:38 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:39:38 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:39:38 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:39:38 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:38 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:38 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:39:40 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 8 Sep 06 10:39:40 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:40 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:40 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 06 10:39:40 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 06 10:39:43 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:39:43 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:39:43 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:39:43 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:43 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:43 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:39:44 music sudo[5352]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 06 10:39:44 music sudo[5352]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 06 10:39:44 music sudo[5352]: pam_unix(sudo:session): session closed for user root Sep 06 10:39:44 music sudo[5355]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 06 10:39:44 music sudo[5355]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 06 10:39:44 music sudo[5355]: pam_unix(sudo:session): session closed for user root Sep 06 10:39:45 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: polling Total Clients: 9 Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::volumioGetVisibleSources Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:45 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 06 10:39:45 music volumio[1010]: info: Received Get System Info Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:39:45 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:45 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:45 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:45 music volumio[1010]: info: Listing playlists Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 06 10:39:45 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 06 10:39:46 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 06 10:39:46 music volumio[1010]: info: Received Get System Info Sep 06 10:39:46 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:39:46 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:39:46 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:39:46 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:46 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:46 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:39:46 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Sep 06 10:39:46 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Sep 06 10:39:49 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 06 10:39:49 music volumio[1010]: info: Received Get System Info Sep 06 10:39:49 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:39:49 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:39:49 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:39:49 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:49 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:49 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:39:49 music volumio[1010]: info: CoreCommandRouter::volumioPlay Sep 06 10:39:49 music volumio[1010]: info: CoreStateMachine::play index undefined Sep 06 10:39:49 music volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 06 10:39:49 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:49 music volumio[1010]: info: CoreStateMachine::startPlaybackTimer Sep 06 10:39:49 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:49 music volumio[1010]: info: [1757129989448] ControllerSpotify::clearAddPlayTrack Sep 06 10:39:49 music volumio[1010]: info: Sending Spotify command with payload to local API: /player/play Sep 06 10:39:49 music go-librespot[4791]: time="2025-09-06T10:39:49+07:00" level=debug msg="resolved context of track" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:49 music go-librespot[4791]: time="2025-09-06T10:39:49+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:49 music go-librespot[4791]: time="2025-09-06T10:39:49+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:49 music go-librespot[4791]: time="2025-09-06T10:39:49+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 10:39:49 music go-librespot[4791]: time="2025-09-06T10:39:49+07:00" level=trace msg="emitting websocket event: will_play" Sep 06 10:39:49 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:39:49 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:39:49 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:39:49 music go-librespot[4791]: time="2025-09-06T10:39:49+07:00" level=debug msg="selected format OGG_VORBIS_320 (364f83cb061295a0aac2c54835362197e39cdd10)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:49 music go-librespot[4791]: time="2025-09-06T10:39:49+07:00" level=debug msg="requested aes key for file 364f83cb061295a0aac2c54835362197e39cdd10, gid: 5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:39:49 music go-librespot[4791]: time="2025-09-06T10:39:49+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:5zXCoF69UxPNLrpar8Rk7e: failed retrieving audio key: failed retrieving aes key with code 1" Sep 06 10:39:49 music volumio[1010]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 06 10:39:50 music volumio[1010]: info: Received Get System Info Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:39:50 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:50 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 06 10:39:50 music volumio[1010]: info: Received Get System Info Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:39:50 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:39:50 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:39:50 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:39:55 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Sep 06 10:40:00 music go-librespot[4791]: time="2025-09-06T10:40:00+07:00" level=trace msg="sent dealer ping" Sep 06 10:40:00 music go-librespot[4791]: time="2025-09-06T10:40:00+07:00" level=trace msg="received dealer pong" Sep 06 10:40:09 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 7 Sep 06 10:40:09 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 8 Sep 06 10:40:09 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: polling Total Clients: 9 Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::volumioGetVisibleSources Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:40:09 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 06 10:40:09 music volumio[1010]: info: Received Get System Info Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:40:09 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:40:09 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:40:09 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:09 music volumio[1010]: info: Listing playlists Sep 06 10:40:09 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 06 10:40:10 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 10 Sep 06 10:40:10 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:40:10 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:10 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 06 10:40:10 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 06 10:40:15 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 9 Sep 06 10:40:15 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:40:15 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:15 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 06 10:40:15 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 06 10:40:16 music volumio[1010]: verbose: New Socket.io Connection to 192.168.1.70 from 192.168.1.9 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 10 Sep 06 10:40:17 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:40:17 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:40:17 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:40:17 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:40:17 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:17 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:40:17 music volumio[1010]: info: CoreCommandRouter::volumioPlay Sep 06 10:40:17 music volumio[1010]: info: CoreStateMachine::play index undefined Sep 06 10:40:17 music volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 06 10:40:17 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:17 music volumio[1010]: info: CoreStateMachine::startPlaybackTimer Sep 06 10:40:17 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:17 music volumio[1010]: info: [1757130017830] ControllerSpotify::clearAddPlayTrack Sep 06 10:40:17 music volumio[1010]: info: Sending Spotify command with payload to local API: /player/play Sep 06 10:40:17 music go-librespot[4791]: time="2025-09-06T10:40:17+07:00" level=debug msg="resolved context of track" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:40:17 music go-librespot[4791]: time="2025-09-06T10:40:17+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:40:17 music go-librespot[4791]: time="2025-09-06T10:40:17+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:40:18 music go-librespot[4791]: time="2025-09-06T10:40:18+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 10:40:18 music go-librespot[4791]: time="2025-09-06T10:40:18+07:00" level=trace msg="emitting websocket event: will_play" Sep 06 10:40:18 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:40:18 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:40:18 music volumio[1010]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5zXCoF69UxPNLrpar8Rk7e","play_origin":"go-librespot"}} Sep 06 10:40:18 music go-librespot[4791]: time="2025-09-06T10:40:18+07:00" level=debug msg="selected format OGG_VORBIS_320 (364f83cb061295a0aac2c54835362197e39cdd10)" uri="spotify:track:5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:40:18 music go-librespot[4791]: time="2025-09-06T10:40:18+07:00" level=debug msg="requested aes key for file 364f83cb061295a0aac2c54835362197e39cdd10, gid: 5zXCoF69UxPNLrpar8Rk7e" Sep 06 10:40:18 music go-librespot[4791]: time="2025-09-06T10:40:18+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:5zXCoF69UxPNLrpar8Rk7e: failed retrieving audio key: failed retrieving aes key with code 1" Sep 06 10:40:18 music volumio[1010]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 06 10:40:24 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 10:40:24 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 10:40:24 music volumio[1010]: info: Discovery: Getting this device information Sep 06 10:40:24 music volumio[1010]: info: CoreCommandRouter::volumioGetState Sep 06 10:40:24 music volumio[1010]: info: CorePlayQueue::getTrack 0 Sep 06 10:40:24 music volumio[1010]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 10:40:30 music go-librespot[4791]: time="2025-09-06T10:40:30+07:00" level=trace msg="received accesspoint ping" Sep 06 10:40:30 music go-librespot[4791]: time="2025-09-06T10:40:30+07:00" level=trace msg="received accesspoint pong ack" Sep 06 10:40:30 music go-librespot[4791]: time="2025-09-06T10:40:30+07:00" level=trace msg="sent dealer ping" Sep 06 10:40:30 music go-librespot[4791]: time="2025-09-06T10:40:30+07:00" level=trace msg="received dealer pong" Sep 06 10:40:31 music volumio[1010]: info: ___________ PLUGINS: Run onVolumioReboot Tasks ___________ Sep 06 10:40:31 music volumio[1010]: info: PLUGIN onReboot : networkfs Sep 06 10:40:31 music volumio[1010]: info: PLUGIN onReboot : audiophonicsonoff Sep 06 10:40:31 music volumio[1010]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 06 10:40:31 music volumio[1010]: TypeError: Cannot read property 'writeSync' of undefined Sep 06 10:40:31 music volumio[1010]: at ControllerAudiophonicsOnOff.onVolumioReboot (/data/plugins/system_hardware/audiophonicsonoff/index.js:40:25) Sep 06 10:40:31 music volumio[1010]: at PluginManager.onVolumioRebootPlugin (/volumio/app/pluginmanager.js:684:30) Sep 06 10:40:31 music volumio[1010]: at HashMap. (/volumio/app/pluginmanager.js:668:31) Sep 06 10:40:31 music volumio[1010]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Sep 06 10:40:31 music volumio[1010]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Sep 06 10:40:31 music volumio[1010]: at PluginManager.onVolumioReboot (/volumio/app/pluginmanager.js:666:20) Sep 06 10:40:31 music volumio[1010]: at CoreCommandRouter.reboot (/volumio/app/index.js:1350:22) Sep 06 10:40:31 music volumio[1010]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:870:33) Sep 06 10:40:31 music volumio[1010]: at Socket.emit (events.js:315:20) Sep 06 10:40:31 music volumio[1010]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Sep 06 10:40:31 music volumio[1010]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Sep 06 10:40:31 music volumio[1010]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 06 10:40:32 music sudo[5482]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-06 10:39 Sep 06 10:40:32 music sudo[5482]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"