-- Logs begin at Fri 2025-05-16 05:25:33 -07, end at Fri 2025-05-16 06:00:49 -07. -- May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand update May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: info: May 16 05:59:00 volumio volumio[997]: ---------------------------- MPD announces state update: update May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand update took 7 milliseconds May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::getState May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: info: May 16 05:59:00 volumio volumio[997]: ---------------------------- MPD announces state update: update May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::getState May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: info: May 16 05:59:00 volumio volumio[997]: ---------------------------- MPD announces state update: update May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::getState May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: info: May 16 05:59:00 volumio volumio[997]: ---------------------------- MPD announces state update: update May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::getState May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 8 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 6 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 6 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 5 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 4 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 3 milliseconds May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: info: Command Router : Notfying DB Updatefalse May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::Close All Modals sent May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: info: Command Router : Notfying DB Updatefalse May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::Close All Modals sent May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: info: Command Router : Notfying DB Updatefalse May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::Close All Modals sent May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::pushState May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::servicePushState May 16 05:59:00 volumio volumio[997]: info: CoreStateMachine::pushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::volumioPushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::pushState May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::servicePushState May 16 05:59:00 volumio volumio[997]: info: CoreStateMachine::pushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::volumioPushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::pushState May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::servicePushState May 16 05:59:00 volumio volumio[997]: info: CoreStateMachine::pushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::volumioPushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 16 05:59:00 volumio volumio[997]: info: ------------------------------ 154ms May 16 05:59:00 volumio volumio[997]: info: ------------------------------ 151ms May 16 05:59:00 volumio volumio[997]: info: ------------------------------ 150ms May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: info: May 16 05:59:00 volumio volumio[997]: ---------------------------- MPD announces state update: update May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::getState May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: info: May 16 05:59:00 volumio volumio[997]: ---------------------------- MPD announces state update: update May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::getState May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::sendMpdCommand status May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 154 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 153 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 5 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 5 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 4 milliseconds May 16 05:59:00 volumio volumio[997]: info: sendMpdCommand status took 3 milliseconds May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: info: Command Router : Notfying DB Updatefalse May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::Close All Modals sent May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: info: Command Router : Notfying DB Updatefalse May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::Close All Modals sent May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: info: Command Router : Notfying DB Updatefalse May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::Close All Modals sent May 16 05:59:00 volumio volumio[997]: verbose: ControllerMpd::parseState May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::pushState May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::servicePushState May 16 05:59:00 volumio volumio[997]: info: CoreStateMachine::pushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::volumioPushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::pushState May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::servicePushState May 16 05:59:00 volumio volumio[997]: info: CoreStateMachine::pushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::volumioPushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 16 05:59:00 volumio volumio[997]: info: ControllerMpd::pushState May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::servicePushState May 16 05:59:00 volumio volumio[997]: info: CoreStateMachine::pushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: CoreCommandRouter::volumioPushState May 16 05:59:00 volumio volumio[997]: info: CorePlayQueue::getTrack 0 May 16 05:59:00 volumio volumio[997]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd May 16 05:59:00 volumio volumio[997]: info: ------------------------------ 268ms May 16 05:59:00 volumio volumio[997]: info: ------------------------------ 120ms May 16 05:59:00 volumio volumio[997]: info: ------------------------------ 118ms May 16 05:59:00 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 May 16 05:59:00 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 May 16 05:59:00 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 May 16 05:59:00 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 May 16 05:59:00 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 May 16 05:59:00 volumio volumio[997]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 May 16 05:59:06 volumio kernel: xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 5 comp_code 1 May 16 05:59:06 volumio kernel: xhci_hcd 0000:00:14.0: Looking for event-dma 000000010cefc670 trb-start 000000010cefc680 trb-end 000000010cefc680 seg-start 000000010cefc000 seg-end 000000010cefcff0 May 16 05:59:17 volumio go-librespot[1551]: time="2025-05-16T05:59:17-07:00" level=debug msg="fetched chunk 4/10, size: 524288" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" May 16 05:59:18 volumio go-librespot[1551]: time="2025-05-16T05:59:18-07:00" level=trace msg="sent dealer ping" May 16 05:59:18 volumio go-librespot[1551]: time="2025-05-16T05:59:18-07:00" level=trace msg="received dealer pong" May 16 05:59:47 volumio go-librespot[1551]: time="2025-05-16T05:59:47-07:00" level=debug msg="fetched chunk 5/10, size: 524288" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" May 16 05:59:48 volumio go-librespot[1551]: time="2025-05-16T05:59:48-07:00" level=trace msg="received accesspoint ping" May 16 05:59:48 volumio go-librespot[1551]: time="2025-05-16T05:59:48-07:00" level=trace msg="received accesspoint pong ack" May 16 05:59:48 volumio go-librespot[1551]: time="2025-05-16T05:59:48-07:00" level=trace msg="sent dealer ping" May 16 05:59:48 volumio go-librespot[1551]: time="2025-05-16T05:59:48-07:00" level=trace msg="received dealer pong" May 16 06:00:17 volumio go-librespot[1551]: time="2025-05-16T06:00:17-07:00" level=debug msg="fetched chunk 6/10, size: 524288" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" May 16 06:00:18 volumio go-librespot[1551]: time="2025-05-16T06:00:18-07:00" level=trace msg="sent dealer ping" May 16 06:00:18 volumio go-librespot[1551]: time="2025-05-16T06:00:18-07:00" level=trace msg="received dealer pong" May 16 06:00:46 volumio go-librespot[1551]: time="2025-05-16T06:00:46-07:00" level=debug msg="fetched chunk 7/10, size: 524288" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" May 16 06:00:48 volumio go-librespot[1551]: time="2025-05-16T06:00:48-07:00" level=trace msg="sent dealer ping" May 16 06:00:48 volumio go-librespot[1551]: time="2025-05-16T06:00:48-07:00" level=trace msg="received dealer pong" May 16 06:00:49 volumio volumio[997]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 16 06:00:49 volumio volumio[997]: Error: connect ETIMEDOUT 151.101.78.79:80 May 16 06:00:49 volumio volumio[997]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { May 16 06:00:49 volumio volumio[997]: errno: -110, May 16 06:00:49 volumio volumio[997]: code: 'ETIMEDOUT', May 16 06:00:49 volumio volumio[997]: syscall: 'connect', May 16 06:00:49 volumio volumio[997]: address: '151.101.78.79', May 16 06:00:49 volumio volumio[997]: port: 80 May 16 06:00:49 volumio volumio[997]: } May 16 06:00:49 volumio volumio[997]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 16 06:00:49 volumio sudo[7132]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-16 05:59 May 16 06:00:49 volumio sudo[7132]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 12:21:23 PM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="a9588e47e4b05f1a05bf70b4acc7555c"