-- Logs begin at Sat 2025-06-28 04:07:50 -07, end at Sat 2025-06-28 04:14:10 -07. -- Jun 28 04:13:01 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:01 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:05 volumio volumio[995]: info: VolumeController::SetAlsaVolume85 Jun 28 04:13:05 volumio volumio[995]: info: CoreStateMachine::pushState Jun 28 04:13:05 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:05 volumio volumio[995]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 28 04:13:05 volumio volumio[995]: info: CoreCommandRouter::volumioPushState Jun 28 04:13:05 volumio volumio[995]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Jun 28 04:13:05 volumio volumio[995]: SPOTIFY: SPOTIFY VOLUME 90 Jun 28 04:13:05 volumio volumio[995]: SPOTIFY: VOLUMIO VOLUME 85 Jun 28 04:13:05 volumio volumio[995]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 28 04:13:05 volumio volumio[995]: info: Setting Spotify Volume from Volumio: 85 Jun 28 04:13:05 volumio go-librespot[1556]: time="2025-06-28T04:13:05-07:00" level=trace msg="sent dealer ping" Jun 28 04:13:05 volumio go-librespot[1556]: time="2025-06-28T04:13:05-07:00" level=trace msg="received dealer pong" Jun 28 04:13:06 volumio volumio[995]: SPOTIFY: SETTING SPOTIFY VOLUME 85 Jun 28 04:13:06 volumio volumio[995]: info: Sending Spotify command with payload to local API: /player/volume Jun 28 04:13:06 volumio go-librespot[1556]: time="2025-06-28T04:13:06-07:00" level=debug msg="update volume to 55704/65535" Jun 28 04:13:08 volumio go-librespot[1556]: time="2025-06-28T04:13:08-07:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 28 04:13:08 volumio go-librespot[1556]: time="2025-06-28T04:13:08-07:00" level=trace msg="emitting websocket event: volume" Jun 28 04:13:08 volumio volumio[995]: SPOTIFY: received: {"type":"volume","data":{"value":85,"max":100}} Jun 28 04:13:08 volumio volumio[995]: SPOTIFY: RECEIVED SPOTIFY VOLUME 85 Jun 28 04:13:12 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:12 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:22 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:22 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:26 volumio ntpd[969]: Soliciting pool server 115.165.161.155 Jun 28 04:13:27 volumio volumio[995]: info: VolumeController::SetAlsaVolume90 Jun 28 04:13:27 volumio volumio[995]: info: CoreStateMachine::pushState Jun 28 04:13:27 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:27 volumio volumio[995]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 28 04:13:27 volumio volumio[995]: info: CoreCommandRouter::volumioPushState Jun 28 04:13:27 volumio volumio[995]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Jun 28 04:13:27 volumio volumio[995]: SPOTIFY: SPOTIFY VOLUME 85 Jun 28 04:13:27 volumio volumio[995]: SPOTIFY: VOLUMIO VOLUME 90 Jun 28 04:13:27 volumio volumio[995]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 28 04:13:27 volumio volumio[995]: info: Setting Spotify Volume from Volumio: 90 Jun 28 04:13:28 volumio ntpd[969]: Soliciting pool server 2400:e920:0:5::14 Jun 28 04:13:28 volumio volumio[995]: SPOTIFY: SETTING SPOTIFY VOLUME 90 Jun 28 04:13:28 volumio volumio[995]: info: Sending Spotify command with payload to local API: /player/volume Jun 28 04:13:28 volumio go-librespot[1556]: time="2025-06-28T04:13:28-07:00" level=debug msg="update volume to 58981/65535" Jun 28 04:13:30 volumio go-librespot[1556]: time="2025-06-28T04:13:30-07:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 28 04:13:30 volumio go-librespot[1556]: time="2025-06-28T04:13:30-07:00" level=trace msg="emitting websocket event: volume" Jun 28 04:13:30 volumio volumio[995]: SPOTIFY: received: {"type":"volume","data":{"value":90,"max":100}} Jun 28 04:13:30 volumio volumio[995]: SPOTIFY: RECEIVED SPOTIFY VOLUME 90 Jun 28 04:13:30 volumio ntpd[969]: Soliciting pool server 103.184.124.254 Jun 28 04:13:32 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:32 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::volumioPause Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::pause Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::stPlaybackTimer Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::servicePause Jun 28 04:13:33 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::servicePause Jun 28 04:13:33 volumio volumio[995]: info: ControllerMpd::pause Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::sendMpdCommand pause Jun 28 04:13:33 volumio volumio[995]: info: Jun 28 04:13:33 volumio volumio[995]: ---------------------------- MPD announces state update: player Jun 28 04:13:33 volumio volumio[995]: info: sendMpdCommand pause took 3 milliseconds Jun 28 04:13:33 volumio volumio[995]: info: ControllerMpd::getState Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::sendMpdCommand status Jun 28 04:13:33 volumio volumio[995]: info: Jun 28 04:13:33 volumio volumio[995]: ---------------------------- MPD announces state update: player Jun 28 04:13:33 volumio volumio[995]: info: ControllerMpd::getState Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::sendMpdCommand status Jun 28 04:13:33 volumio volumio[995]: info: Jun 28 04:13:33 volumio volumio[995]: ---------------------------- MPD announces state update: player Jun 28 04:13:33 volumio volumio[995]: info: ControllerMpd::getState Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::sendMpdCommand status Jun 28 04:13:33 volumio volumio[995]: info: sendMpdCommand status took 3 milliseconds Jun 28 04:13:33 volumio volumio[995]: info: sendMpdCommand status took 2 milliseconds Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::parseState Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::parseState Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 28 04:13:33 volumio volumio[995]: info: sendMpdCommand status took 2 milliseconds Jun 28 04:13:33 volumio volumio[995]: info: sendMpdCommand playlistinfo took 2 milliseconds Jun 28 04:13:33 volumio volumio[995]: info: sendMpdCommand playlistinfo took 1 milliseconds Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::parseState Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::parseTrackInfo Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::parseTrackInfo Jun 28 04:13:33 volumio volumio[995]: info: ControllerMpd::pushState Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::servicePushState Jun 28 04:13:33 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:33 volumio volumio[995]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":50723,"duration":402,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"719 Kbps","isStreaming":false,"title":"Mười Năm Tình Cũ","artist":"Chế Linh","album":"Hát Cho Người Tình Phụ","uri":"USB/WD_BLACK/Chế Linh đặc biệt/01_Mười Năm Tình Cũ.flac","trackType":"flac"} Jun 28 04:13:33 volumio volumio[995]: verbose: CURRENT POSITION 0 Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::syncState stateService pause Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::syncState currentStatus pause Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::pushState Jun 28 04:13:33 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::volumioPushState Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::stPlaybackTimer Jun 28 04:13:33 volumio volumio[995]: info: ControllerMpd::pushState Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::servicePushState Jun 28 04:13:33 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:33 volumio volumio[995]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":50723,"duration":402,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"719 Kbps","isStreaming":false,"title":"Mười Năm Tình Cũ","artist":"Chế Linh","album":"Hát Cho Người Tình Phụ","uri":"USB/WD_BLACK/Chế Linh đặc biệt/01_Mười Năm Tình Cũ.flac","trackType":"flac"} Jun 28 04:13:33 volumio volumio[995]: verbose: CURRENT POSITION 0 Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::syncState stateService pause Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::syncState currentStatus pause Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::pushState Jun 28 04:13:33 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::volumioPushState Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::stPlaybackTimer Jun 28 04:13:33 volumio volumio[995]: info: ------------------------------ 23ms Jun 28 04:13:33 volumio volumio[995]: info: ------------------------------ 23ms Jun 28 04:13:33 volumio volumio[995]: info: sendMpdCommand playlistinfo took 21 milliseconds Jun 28 04:13:33 volumio volumio[995]: verbose: ControllerMpd::parseTrackInfo Jun 28 04:13:33 volumio volumio[995]: info: ControllerMpd::pushState Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::servicePushState Jun 28 04:13:33 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:33 volumio volumio[995]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":50723,"duration":402,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"719 Kbps","isStreaming":false,"title":"Mười Năm Tình Cũ","artist":"Chế Linh","album":"Hát Cho Người Tình Phụ","uri":"USB/WD_BLACK/Chế Linh đặc biệt/01_Mười Năm Tình Cũ.flac","trackType":"flac"} Jun 28 04:13:33 volumio volumio[995]: verbose: CURRENT POSITION 0 Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::syncState stateService pause Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::syncState currentStatus pause Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::pushState Jun 28 04:13:33 volumio volumio[995]: info: CorePlayQueue::getTrack 0 Jun 28 04:13:33 volumio volumio[995]: info: CoreCommandRouter::volumioPushState Jun 28 04:13:33 volumio volumio[995]: info: CoreStateMachine::stPlaybackTimer Jun 28 04:13:33 volumio volumio[995]: info: ------------------------------ 35ms Jun 28 04:13:33 volumio volumio[995]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Jun 28 04:13:33 volumio volumio[995]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Jun 28 04:13:35 volumio go-librespot[1556]: time="2025-06-28T04:13:35-07:00" level=trace msg="sent dealer ping" Jun 28 04:13:35 volumio go-librespot[1556]: time="2025-06-28T04:13:35-07:00" level=trace msg="received dealer pong" Jun 28 04:13:42 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:42 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:53 volumio kernel: EDID block 0 is all zeroes Jun 28 04:13:53 volumio kernel: EDID block 0 is all zeroes Jun 28 04:14:03 volumio kernel: EDID block 0 is all zeroes Jun 28 04:14:03 volumio kernel: EDID block 0 is all zeroes Jun 28 04:14:05 volumio go-librespot[1556]: time="2025-06-28T04:14:05-07:00" level=trace msg="received accesspoint ping" Jun 28 04:14:05 volumio go-librespot[1556]: time="2025-06-28T04:14:05-07:00" level=trace msg="received accesspoint pong ack" Jun 28 04:14:05 volumio go-librespot[1556]: time="2025-06-28T04:14:05-07:00" level=trace msg="sent dealer ping" Jun 28 04:14:05 volumio go-librespot[1556]: time="2025-06-28T04:14:05-07:00" level=trace msg="received dealer pong" Jun 28 04:14:10 volumio volumio[995]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 28 04:14:10 volumio volumio[995]: Error: connect ETIMEDOUT 151.101.78.79:443 Jun 28 04:14:10 volumio volumio[995]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Jun 28 04:14:10 volumio volumio[995]: errno: -110, Jun 28 04:14:10 volumio volumio[995]: code: 'ETIMEDOUT', Jun 28 04:14:10 volumio volumio[995]: syscall: 'connect', Jun 28 04:14:10 volumio volumio[995]: address: '151.101.78.79', Jun 28 04:14:10 volumio volumio[995]: port: 443 Jun 28 04:14:10 volumio volumio[995]: } Jun 28 04:14:10 volumio volumio[995]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 28 04:14:10 volumio sudo[2976]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-28 04:13 Jun 28 04:14:10 volumio sudo[2976]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:50:12 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="39b0f8c200b2dcadf117e189b4b3632d"