Dec 26 10:51:00 volumio mpd[5243]: 2025-12-26T10:51:00 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 10:51:00 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 26 10:51:00 volumio sudo[5197]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:00 volumio volumio[1149]: error: updateQueue error: null Dec 26 10:51:01 volumio volumio[1149]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Dec 26 10:51:01 volumio volumio[1149]: info: CoreStateMachine::getcurrentVolume Dec 26 10:51:01 volumio volumio[1149]: info: CoreCommandRouter::volumioRetrievevolume Dec 26 10:51:01 volumio volumio[1149]: info: CoreStateMachine::pushState Dec 26 10:51:01 volumio volumio[1149]: info: CorePlayQueue::getTrack 0 Dec 26 10:51:01 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 26 10:51:01 volumio volumio[1149]: info: CoreCommandRouter::volumioPushState Dec 26 10:51:03 volumio sudo[5262]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 10:51:03 volumio sudo[5262]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:03 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 10:51:03 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 10:51:03 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 10:51:03 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 10:51:03 volumio sudo[5262]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:03 volumio mpd_monitor.sh[5264]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 10:51:03 volumio volumio[1149]: info: Successfully started MPD Monitor Dec 26 10:51:11 volumio volumio[1149]: info: CALLMETHOD: audio_interface alsa_controller saveResamplingOpts [object Object] Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveResamplingOpts Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: mpd , saveResampleOptions Dec 26 10:51:11 volumio sudo[5292]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio sudo[5292]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:11 volumio sudo[5294]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 26 10:51:11 volumio sudo[5294]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:11 volumio sudo[5292]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 26 10:51:11 volumio volumio[1149]: info: MPD Permissions set Dec 26 10:51:11 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 26 10:51:11 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 26 10:51:11 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 26 10:51:11 volumio systemd[1]: mpd.service: Consumed 1.782s CPU time. Dec 26 10:51:11 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 26 10:51:11 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 26 10:51:11 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 26 10:51:11 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 26 10:51:11 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 26 10:51:11 volumio sudo[5303]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 26 10:51:11 volumio sudo[5303]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 10:51:11 volumio sudo[5303]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:12 volumio mpd[5305]: 2025-12-26T10:51:12 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 26 10:51:12 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 26 10:51:12 volumio sudo[5294]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:12 volumio volumio[1149]: error: updateQueue error: null Dec 26 10:51:15 volumio sudo[5309]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 26 10:51:15 volumio sudo[5309]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:15 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 26 10:51:15 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 26 10:51:15 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 26 10:51:16 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 26 10:51:16 volumio mpd_monitor.sh[5311]: MPD Monitor Service: Starting MPD Monitor Service Dec 26 10:51:16 volumio sudo[5309]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:16 volumio volumio[1149]: info: Successfully started MPD Monitor Dec 26 10:51:17 volumio go-librespot[4970]: time="2025-12-26T10:51:17+09:00" level=trace msg="sent dealer ping" Dec 26 10:51:18 volumio go-librespot[4970]: time="2025-12-26T10:51:18+09:00" level=trace msg="received dealer pong" Dec 26 10:51:20 volumio volumio[1149]: info: CoreCommandRouter::volumioGetState Dec 26 10:51:20 volumio volumio[1149]: info: CorePlayQueue::getTrack 0 Dec 26 10:51:22 volumio volumio[1149]: info: CoreCommandRouter::volumioPlay Dec 26 10:51:22 volumio volumio[1149]: info: CoreStateMachine::play index undefined Dec 26 10:51:22 volumio volumio[1149]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 10:51:22 volumio volumio[1149]: info: CorePlayQueue::getTrack 0 Dec 26 10:51:22 volumio volumio[1149]: info: CoreStateMachine::startPlaybackTimer Dec 26 10:51:22 volumio volumio[1149]: info: CorePlayQueue::getTrack 0 Dec 26 10:51:22 volumio volumio[1149]: info: [1766713882039] ControllerSpotify::clearAddPlayTrack Dec 26 10:51:22 volumio volumio[1149]: info: Sending Spotify command with payload to local API: /player/play Dec 26 10:51:22 volumio go-librespot[4970]: time="2025-12-26T10:51:22+09:00" level=debug msg="resolved context of track" uri="spotify:track:1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:22 volumio go-librespot[4970]: time="2025-12-26T10:51:22+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:22 volumio go-librespot[4970]: time="2025-12-26T10:51:22+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:22 volumio go-librespot[4970]: time="2025-12-26T10:51:22+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 10:51:22 volumio go-librespot[4970]: time="2025-12-26T10:51:22+09:00" level=trace msg="emitting websocket event: will_play" Dec 26 10:51:22 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","play_origin":"go-librespot"}} Dec 26 10:51:22 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","play_origin":"go-librespot"}} Dec 26 10:51:22 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","play_origin":"go-librespot"}} Dec 26 10:51:22 volumio go-librespot[4970]: time="2025-12-26T10:51:22+09:00" level=debug msg="selected format OGG_VORBIS_320 (11c799294ce0c9a3750e86279a24711d2535e3ac)" uri="spotify:track:1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:22 volumio go-librespot[4970]: time="2025-12-26T10:51:22+09:00" level=debug msg="requested aes key for file 11c799294ce0c9a3750e86279a24711d2535e3ac, gid: 1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:22 volumio go-librespot[4970]: time="2025-12-26T10:51:22+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1k0JAiH11gHL9dc5dfQjQr: failed retrieving audio key: failed retrieving aes key with code 1" Dec 26 10:51:22 volumio volumio[1149]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 26 10:51:31 volumio volumio[1149]: info: CoreCommandRouter::volumioPlay Dec 26 10:51:31 volumio volumio[1149]: info: CoreStateMachine::play index undefined Dec 26 10:51:31 volumio volumio[1149]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 10:51:31 volumio volumio[1149]: info: CorePlayQueue::getTrack 0 Dec 26 10:51:31 volumio volumio[1149]: info: CoreStateMachine::startPlaybackTimer Dec 26 10:51:31 volumio volumio[1149]: info: CorePlayQueue::getTrack 0 Dec 26 10:51:31 volumio volumio[1149]: info: [1766713891199] ControllerSpotify::clearAddPlayTrack Dec 26 10:51:31 volumio volumio[1149]: info: Sending Spotify command with payload to local API: /player/play Dec 26 10:51:31 volumio go-librespot[4970]: time="2025-12-26T10:51:31+09:00" level=debug msg="resolved context of track" uri="spotify:track:1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:31 volumio go-librespot[4970]: time="2025-12-26T10:51:31+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:31 volumio go-librespot[4970]: time="2025-12-26T10:51:31+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:31 volumio go-librespot[4970]: time="2025-12-26T10:51:31+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 10:51:31 volumio go-librespot[4970]: time="2025-12-26T10:51:31+09:00" level=trace msg="emitting websocket event: will_play" Dec 26 10:51:31 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","play_origin":"go-librespot"}} Dec 26 10:51:31 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","play_origin":"go-librespot"}} Dec 26 10:51:31 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","uri":"spotify:track:1k0JAiH11gHL9dc5dfQjQr","play_origin":"go-librespot"}} Dec 26 10:51:31 volumio go-librespot[4970]: time="2025-12-26T10:51:31+09:00" level=debug msg="selected format OGG_VORBIS_320 (11c799294ce0c9a3750e86279a24711d2535e3ac)" uri="spotify:track:1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:31 volumio go-librespot[4970]: time="2025-12-26T10:51:31+09:00" level=debug msg="requested aes key for file 11c799294ce0c9a3750e86279a24711d2535e3ac, gid: 1k0JAiH11gHL9dc5dfQjQr" Dec 26 10:51:31 volumio go-librespot[4970]: time="2025-12-26T10:51:31+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1k0JAiH11gHL9dc5dfQjQr: failed retrieving audio key: failed retrieving aes key with code 1" Dec 26 10:51:31 volumio volumio[1149]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 26 10:51:35 volumio volumio[1149]: info: CoreCommandRouter::volumioNext Dec 26 10:51:35 volumio volumio[1149]: info: CoreStateMachine::next Dec 26 10:51:35 volumio volumio[1149]: info: CoreStateMachine::stop Dec 26 10:51:35 volumio volumio[1149]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 10:51:35 volumio volumio[1149]: info: CoreStateMachine::play index undefined Dec 26 10:51:35 volumio volumio[1149]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 10:51:35 volumio volumio[1149]: info: CorePlayQueue::getTrack 1 Dec 26 10:51:35 volumio volumio[1149]: info: CoreStateMachine::startPlaybackTimer Dec 26 10:51:35 volumio volumio[1149]: info: CorePlayQueue::getTrack 1 Dec 26 10:51:35 volumio volumio[1149]: info: [1766713895920] ControllerSpotify::clearAddPlayTrack Dec 26 10:51:35 volumio volumio[1149]: info: Sending Spotify command with payload to local API: /player/play Dec 26 10:51:35 volumio volumio[1149]: info: CoreStateMachine::updateTrackBlock Dec 26 10:51:35 volumio volumio[1149]: info: CorePlayQueue::getTrackBlock Dec 26 10:51:35 volumio go-librespot[4970]: time="2025-12-26T10:51:35+09:00" level=debug msg="resolved context of track" uri="spotify:track:4eCan7Jb3q0xQ1FAELOtEz" Dec 26 10:51:35 volumio go-librespot[4970]: time="2025-12-26T10:51:35+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4eCan7Jb3q0xQ1FAELOtEz" Dec 26 10:51:35 volumio go-librespot[4970]: time="2025-12-26T10:51:35+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4eCan7Jb3q0xQ1FAELOtEz" Dec 26 10:51:36 volumio go-librespot[4970]: time="2025-12-26T10:51:36+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 10:51:36 volumio go-librespot[4970]: time="2025-12-26T10:51:36+09:00" level=trace msg="emitting websocket event: will_play" Dec 26 10:51:36 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4eCan7Jb3q0xQ1FAELOtEz","uri":"spotify:track:4eCan7Jb3q0xQ1FAELOtEz","play_origin":"go-librespot"}} Dec 26 10:51:36 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4eCan7Jb3q0xQ1FAELOtEz","uri":"spotify:track:4eCan7Jb3q0xQ1FAELOtEz","play_origin":"go-librespot"}} Dec 26 10:51:36 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4eCan7Jb3q0xQ1FAELOtEz","uri":"spotify:track:4eCan7Jb3q0xQ1FAELOtEz","play_origin":"go-librespot"}} Dec 26 10:51:36 volumio go-librespot[4970]: time="2025-12-26T10:51:36+09:00" level=debug msg="selected format OGG_VORBIS_320 (561287046c25e05a51eed22e96c22d69c9b45fa3)" uri="spotify:track:4eCan7Jb3q0xQ1FAELOtEz" Dec 26 10:51:36 volumio go-librespot[4970]: time="2025-12-26T10:51:36+09:00" level=debug msg="requested aes key for file 561287046c25e05a51eed22e96c22d69c9b45fa3, gid: 4eCan7Jb3q0xQ1FAELOtEz" Dec 26 10:51:36 volumio go-librespot[4970]: time="2025-12-26T10:51:36+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4eCan7Jb3q0xQ1FAELOtEz: failed retrieving audio key: failed retrieving aes key with code 1" Dec 26 10:51:36 volumio volumio[1149]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 26 10:51:38 volumio volumio[1149]: info: CoreCommandRouter::volumioNext Dec 26 10:51:38 volumio volumio[1149]: info: CoreStateMachine::next Dec 26 10:51:38 volumio volumio[1149]: info: CoreStateMachine::stop Dec 26 10:51:38 volumio volumio[1149]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 10:51:38 volumio volumio[1149]: info: CoreStateMachine::play index undefined Dec 26 10:51:38 volumio volumio[1149]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 26 10:51:38 volumio volumio[1149]: info: CorePlayQueue::getTrack 2 Dec 26 10:51:38 volumio volumio[1149]: info: CoreStateMachine::startPlaybackTimer Dec 26 10:51:38 volumio volumio[1149]: info: CorePlayQueue::getTrack 2 Dec 26 10:51:38 volumio volumio[1149]: info: [1766713898295] ControllerSpotify::clearAddPlayTrack Dec 26 10:51:38 volumio volumio[1149]: info: Sending Spotify command with payload to local API: /player/play Dec 26 10:51:38 volumio volumio[1149]: info: CoreStateMachine::updateTrackBlock Dec 26 10:51:38 volumio volumio[1149]: info: CorePlayQueue::getTrackBlock Dec 26 10:51:38 volumio go-librespot[4970]: time="2025-12-26T10:51:38+09:00" level=debug msg="resolved context of track" uri="spotify:track:3WvM2dIR9iIxMGNMP7WsNw" Dec 26 10:51:38 volumio go-librespot[4970]: time="2025-12-26T10:51:38+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3WvM2dIR9iIxMGNMP7WsNw" Dec 26 10:51:38 volumio go-librespot[4970]: time="2025-12-26T10:51:38+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3WvM2dIR9iIxMGNMP7WsNw" Dec 26 10:51:38 volumio go-librespot[4970]: time="2025-12-26T10:51:38+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 26 10:51:38 volumio go-librespot[4970]: time="2025-12-26T10:51:38+09:00" level=trace msg="emitting websocket event: will_play" Dec 26 10:51:38 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3WvM2dIR9iIxMGNMP7WsNw","uri":"spotify:track:3WvM2dIR9iIxMGNMP7WsNw","play_origin":"go-librespot"}} Dec 26 10:51:38 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3WvM2dIR9iIxMGNMP7WsNw","uri":"spotify:track:3WvM2dIR9iIxMGNMP7WsNw","play_origin":"go-librespot"}} Dec 26 10:51:38 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3WvM2dIR9iIxMGNMP7WsNw","uri":"spotify:track:3WvM2dIR9iIxMGNMP7WsNw","play_origin":"go-librespot"}} Dec 26 10:51:38 volumio go-librespot[4970]: time="2025-12-26T10:51:38+09:00" level=debug msg="selected format OGG_VORBIS_320 (5b93a14c2a14b051bd65e2963ef38bcff3ae9a03)" uri="spotify:track:3WvM2dIR9iIxMGNMP7WsNw" Dec 26 10:51:38 volumio go-librespot[4970]: time="2025-12-26T10:51:38+09:00" level=debug msg="requested aes key for file 5b93a14c2a14b051bd65e2963ef38bcff3ae9a03, gid: 3WvM2dIR9iIxMGNMP7WsNw" Dec 26 10:51:38 volumio go-librespot[4970]: time="2025-12-26T10:51:38+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3WvM2dIR9iIxMGNMP7WsNw: failed retrieving audio key: failed retrieving aes key with code 1" Dec 26 10:51:38 volumio volumio[1149]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 26 10:51:42 volumio volumio[1149]: info: CoreCommandRouter::volumioGetState Dec 26 10:51:42 volumio volumio[1149]: info: CorePlayQueue::getTrack 2 Dec 26 10:51:44 volumio volumio[1149]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 26 10:51:44 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 26 10:51:44 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Dec 26 10:51:44 volumio sudo[5387]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Dec 26 10:51:44 volumio sudo[5387]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:44 volumio sudo[5392]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Dec 26 10:51:44 volumio sudo[5392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:44 volumio sudo[5387]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:44 volumio sudo[5398]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Dec 26 10:51:44 volumio sudo[5398]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:44 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache Dec 26 10:51:44 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks Dec 26 10:51:44 volumio sudo[5392]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:44 volumio sudo[5403]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Dec 26 10:51:44 volumio sudo[5403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:44 volumio sudo[5398]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:44 volumio sudo[5403]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:44 volumio sudo[5412]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 10:51:44 volumio sudo[5407]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 26 10:51:44 volumio sudo[5412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:44 volumio sudo[5407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:44 volumio sudo[5412]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:44 volumio sudo[5407]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:44 volumio sudo[5417]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 26 10:51:44 volumio sudo[5417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:51:47 volumio go-librespot[4970]: time="2025-12-26T10:51:47+09:00" level=trace msg="received accesspoint ping" Dec 26 10:51:47 volumio sudo[5417]: pam_unix(sudo:session): session closed for user root Dec 26 10:51:47 volumio go-librespot[4970]: time="2025-12-26T10:51:47+09:00" level=trace msg="received accesspoint pong ack" Dec 26 10:51:47 volumio go-librespot[4970]: time="2025-12-26T10:51:47+09:00" level=trace msg="sent dealer ping" Dec 26 10:51:48 volumio go-librespot[4970]: time="2025-12-26T10:51:48+09:00" level=trace msg="received dealer pong" Dec 26 10:52:17 volumio go-librespot[4970]: time="2025-12-26T10:52:17+09:00" level=trace msg="sent dealer ping" Dec 26 10:52:18 volumio go-librespot[4970]: time="2025-12-26T10:52:18+09:00" level=trace msg="received dealer pong" Dec 26 10:52:27 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: network , saveWirelessNetworkSettings Dec 26 10:52:27 volumio volumio[1149]: info: Saving new wireless network Dec 26 10:52:27 volumio sudo[5511]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/wpa_supplicant/wpa_supplicant.conf Dec 26 10:52:27 volumio sudo[5511]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:27 volumio sudo[5511]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:27 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , onNetworkingRestart Dec 26 10:52:27 volumio volumio[1149]: info: Discovery: Restarting Advertising due to device name change Dec 26 10:52:27 volumio sudo[5514]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart wireless.service Dec 26 10:52:27 volumio sudo[5514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:27 volumio systemd[1]: Stopping wireless.service - Wireless Services... Dec 26 10:52:27 volumio systemd[1]: wireless.service: Deactivated successfully. Dec 26 10:52:27 volumio systemd[1]: Stopped wireless.service - Wireless Services. Dec 26 10:52:27 volumio systemd[1]: Starting wireless.service - Wireless Services... Dec 26 10:52:27 volumio wireless.js[5520]: WIRELESS.JS: Single Network Mode enabled, only one network device can be active at a time between ethernet and wireless Dec 26 10:52:27 volumio wireless.js[5520]: WIRELESS.JS: Wired network status changed to: ---connected--- Dec 26 10:52:27 volumio wireless.js[5520]: WIRELESS.JS: Wireless.js initializing wireless flow Dec 26 10:52:27 volumio wireless.js[5520]: WIRELESS.JS: Cleaning previous... Dec 26 10:52:28 volumio sudo[5538]: root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/ip addr flush dev wlan0 Dec 26 10:52:28 volumio sudo[5538]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 10:52:28 volumio sudo[5538]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:28 volumio sudo[5540]: root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/ifconfig wlan0 down Dec 26 10:52:28 volumio sudo[5540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 26 10:52:28 volumio volumio[1149]: info: Discovery: A device disappeared from network Dec 26 10:52:28 volumio volumio[1149]: info: Discovery: Device volumio disappeared from network Dec 26 10:52:28 volumio volumio[1149]: info: Discovery: A device disappeared from network Dec 26 10:52:28 volumio sudo[5540]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:28 volumio sudo[5543]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 10:52:28 volumio sudo[5543]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:28 volumio sudo[5543]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:28 volumio wireless.js[5520]: WIRELESS.JS: Stopped aP Dec 26 10:52:28 volumio sudo[5551]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Dec 26 10:52:28 volumio sudo[5551]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:28 volumio sudo[5551]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:28 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Dec 26 10:52:28 volumio sudo[5553]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Dec 26 10:52:28 volumio sudo[5553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:28 volumio sudo[5553]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:28 volumio sudo[5561]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Dec 26 10:52:28 volumio sudo[5561]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:28 volumio sudo[5561]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:28 volumio sudo[5563]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Dec 26 10:52:28 volumio sudo[5563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:29 volumio sudo[5568]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 10:52:29 volumio sudo[5568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:29 volumio sudo[5568]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:30 volumio sudo[5585]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 10:52:30 volumio sudo[5585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:30 volumio sudo[5585]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:31 volumio sudo[5588]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 10:52:31 volumio sudo[5588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:31 volumio sudo[5588]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:31 volumio sudo[5563]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:31 volumio wireless.js[5520]: WIRELESS.JS: SETTING APPROPRIATE REG DOMAIN: KR Dec 26 10:52:31 volumio sudo[5592]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Dec 26 10:52:31 volumio sudo[5592]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:31 volumio sudo[5592]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:31 volumio sudo[5594]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set KR Dec 26 10:52:31 volumio sudo[5594]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:31 volumio sudo[5594]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:31 volumio wireless.js[5520]: WIRELESS.JS: SUCCESSFULLY SET NEW REGDOMAIN: KR Dec 26 10:52:31 volumio wireless.js[5520]: WIRELESS.JS: Single Network Mode: Wired network active, not starting wireless flow Dec 26 10:52:31 volumio wireless.js[5520]: WIRELESS.JS: Notified systemd about wireless ready Dec 26 10:52:31 volumio systemd[1]: Started wireless.service - Wireless Services. Dec 26 10:52:31 volumio sudo[5514]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:31 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Dec 26 10:52:32 volumio volumio[1149]: info: Discovery: Started advertising with name: Volumio Dec 26 10:52:32 volumio sudo[5603]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 26 10:52:32 volumio sudo[5603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 26 10:52:32 volumio sudo[5603]: pam_unix(sudo:session): session closed for user root Dec 26 10:52:33 volumio volumio[1149]: compat.c: read() failed: Resource temporarily unavailable Dec 26 10:52:33 volumio volumio[1149]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 10:52:33 volumio volumio[1149]: Error: dns service error: unknown Dec 26 10:52:33 volumio volumio[1149]: at MDNSService.self.watcher.callback (/volumio/node_modules/mdns/lib/mdns_service.js:18:40) { Dec 26 10:52:33 volumio volumio[1149]: errorCode: -65537 Dec 26 10:52:33 volumio volumio[1149]: } Dec 26 10:52:33 volumio volumio[1149]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 26 10:52:33 volumio sudo[5620]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 10:51' Dec 26 10:52:33 volumio sudo[5620]: 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"