-- Logs begin at Mon 2025-07-07 06:44:30 +07, end at Mon 2025-07-07 07:09:57 +07. -- Jul 07 07:08:01 volumio go-librespot[1605]: time="2025-07-07T07:08:01+07:00" level=trace msg="sent dealer ping" Jul 07 07:08:01 volumio go-librespot[1605]: time="2025-07-07T07:08:01+07:00" level=trace msg="received dealer pong" Jul 07 07:08:13 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:08:13 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:08:13 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 07 07:08:13 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:08:13 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:08:13 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:08:13 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:08:13 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:08:13 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:08:13 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:08:14 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:08:20 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:08:20 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:08:20 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:08:20 volumio shairport-sync[1634]: {"time":1751846861101,"response":"startAirplayPlayback Success"} % Total % Received % Xferd Average Speed Time Time Time Current Jul 07 07:08:20 volumio shairport-sync[1634]: Dload Upload Total Spent Left Speed Jul 07 07:08:20 volumio volumio[941]: info: Jul 07 07:08:20 volumio volumio[941]: ---------------------------- Client requests Stop Airplay Playback Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , stopAirplayPlayback Jul 07 07:08:20 volumio volumio[941]: info: Airplay playback stop Jul 07 07:08:20 volumio volumio[941]: info: Airplay Playback Stopped, clearing state Jul 07 07:08:20 volumio volumio[941]: info: CoreStateMachine::resetVolumioState Jul 07 07:08:20 volumio volumio[941]: info: CoreStateMachine::getcurrentVolume Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::volumioRetrievevolume Jul 07 07:08:20 volumio shairport-sync[1634]: [158B blob data] Jul 07 07:08:20 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:08:20 volumio volumio[941]: info: CoreStateMachine::updateTrackBlock Jul 07 07:08:20 volumio volumio[941]: info: CorePlayQueue::getTrackBlock Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::volumioRetrievevolume Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:08:20 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:08:20 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:08:20 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:08:22 volumio volumio[941]: error: error Jul 07 07:08:31 volumio go-librespot[1605]: time="2025-07-07T07:08:31+07:00" level=trace msg="sent dealer ping" Jul 07 07:08:32 volumio go-librespot[1605]: time="2025-07-07T07:08:32+07:00" level=trace msg="received dealer pong" Jul 07 07:08:42 volumio ntpd[1288]: Soliciting pool server 103.199.19.135 Jul 07 07:08:45 volumio ntpd[1288]: Soliciting pool server 2401:5f80:5001:1f::31f Jul 07 07:08:45 volumio ntpd[1288]: Soliciting pool server 103.184.124.254 Jul 07 07:08:49 volumio ntpd[1288]: Soliciting pool server 103.199.19.135 Jul 07 07:09:01 volumio go-librespot[1605]: time="2025-07-07T07:09:01+07:00" level=trace msg="received accesspoint ping" Jul 07 07:09:01 volumio go-librespot[1605]: time="2025-07-07T07:09:01+07:00" level=trace msg="received accesspoint pong ack" Jul 07 07:09:01 volumio go-librespot[1605]: time="2025-07-07T07:09:01+07:00" level=trace msg="sent dealer ping" Jul 07 07:09:01 volumio go-librespot[1605]: time="2025-07-07T07:09:01+07:00" level=trace msg="received dealer pong" Jul 07 07:09:07 volumio volumio[941]: info: Airplay started streaming, receiving metadatas Jul 07 07:09:07 volumio shairport-sync[1634]: {"time":1751846900750,"response":"stopAirplayPlayback Success"} % Total % Received % Xferd Average Speed Time Time Time Current Jul 07 07:09:07 volumio shairport-sync[1634]: Dload Upload Total Spent Left Speed Jul 07 07:09:07 volumio volumio[941]: info: Jul 07 07:09:07 volumio volumio[941]: ---------------------------- Client requests Start Airplay PlaybackRoutine Jul 07 07:09:07 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Jul 07 07:09:07 volumio volumio[941]: info: Airplay playback start Jul 07 07:09:07 volumio shairport-sync[1634]: [158B blob data] Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:08 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:08 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:08 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:08 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:08 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:08 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:09 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:09 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:09 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:09 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:09 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::servicePushState Jul 07 07:09:09 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:09 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 58 Jul 07 07:09:09 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:12 volumio volumio[941]: error: error Jul 07 07:09:14 volumio volumio[941]: info: Updating volume from AirPlay: -11.87; 60% Jul 07 07:09:14 volumio volumio[941]: info: VolumeController::SetAlsaVolume60 Jul 07 07:09:14 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:14 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 07 07:09:14 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:14 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Jul 07 07:09:14 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 58 Jul 07 07:09:14 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 60 Jul 07 07:09:14 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 07 07:09:14 volumio volumio[941]: info: Setting Spotify Volume from Volumio: 60 Jul 07 07:09:14 volumio volumio[941]: info: Updating volume from AirPlay: -11.56; 61% Jul 07 07:09:14 volumio volumio[941]: info: VolumeController::SetAlsaVolume61 Jul 07 07:09:14 volumio volumio[941]: info: CoreStateMachine::pushState Jul 07 07:09:14 volumio volumio[941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 07 07:09:14 volumio volumio[941]: info: CoreCommandRouter::volumioPushState Jul 07 07:09:14 volumio volumio[941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Jul 07 07:09:14 volumio volumio[941]: SPOTIFY: SPOTIFY VOLUME 60 Jul 07 07:09:14 volumio volumio[941]: SPOTIFY: VOLUMIO VOLUME 61 Jul 07 07:09:14 volumio volumio[941]: SPOTIFY: DELTA VOLUME ENOUGH: false Jul 07 07:09:16 volumio volumio[941]: SPOTIFY: SETTING SPOTIFY VOLUME 60 Jul 07 07:09:16 volumio volumio[941]: info: Sending Spotify command with payload to local API: /player/volume Jul 07 07:09:16 volumio go-librespot[1605]: time="2025-07-07T07:09:16+07:00" level=debug msg="update volume to 39321/65535" Jul 07 07:09:17 volumio go-librespot[1605]: time="2025-07-07T07:09:17+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 07 07:09:17 volumio go-librespot[1605]: time="2025-07-07T07:09:17+07:00" level=trace msg="emitting websocket event: volume" Jul 07 07:09:17 volumio volumio[941]: SPOTIFY: received: {"type":"volume","data":{"value":60,"max":100}} Jul 07 07:09:17 volumio volumio[941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 60 Jul 07 07:09:31 volumio go-librespot[1605]: time="2025-07-07T07:09:31+07:00" level=trace msg="sent dealer ping" Jul 07 07:09:31 volumio go-librespot[1605]: time="2025-07-07T07:09:31+07:00" level=trace msg="received dealer pong" Jul 07 07:09:47 volumio ntpd[1288]: Soliciting pool server 103.184.124.254 Jul 07 07:09:50 volumio ntpd[1288]: Soliciting pool server 2400:6760:0:200::254 Jul 07 07:09:52 volumio ntpd[1288]: Soliciting pool server 103.188.82.179 Jul 07 07:09:54 volumio ntpd[1288]: Soliciting pool server 115.165.161.155 Jul 07 07:09:57 volumio volumio[941]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 07 07:09:57 volumio volumio[941]: Error: connect ETIMEDOUT 151.101.78.79:443 Jul 07 07:09:57 volumio volumio[941]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Jul 07 07:09:57 volumio volumio[941]: errno: -110, Jul 07 07:09:57 volumio volumio[941]: code: 'ETIMEDOUT', Jul 07 07:09:57 volumio volumio[941]: syscall: 'connect', Jul 07 07:09:57 volumio volumio[941]: address: '151.101.78.79', Jul 07 07:09:57 volumio volumio[941]: port: 443 Jul 07 07:09:57 volumio volumio[941]: } Jul 07 07:09:57 volumio volumio[941]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 07 07:09:57 volumio sudo[5583]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-07 07:08 Jul 07 07:09:57 volumio sudo[5583]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 02 Jul 2025 04:41:06 PM CEST" VOLUMIO_VERSION="3.819" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="097e6b8b481766e7a0f9527e4a34a29b"