Aug 31 18:21:08 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.122 Aug 31 18:21:08 volumio bluetoothd[810]: Adv Monitor app :1.122 disconnected from D-Bus Aug 31 18:21:08 volumio volumio[1202]: info: [Wireless Output Manager][Bluetooth] Reconnecting preferred device 1C:D3:AF:4D:08:3B Aug 31 18:21:08 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.123 Aug 31 18:21:13 volumio bluetoothd[810]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 1C:D3:AF:4D:08:3B: Host is down (112) Aug 31 18:21:13 volumio volumio[1202]: warn: [Wireless Output Manager][Bluetooth] Preferred speaker is unavailable: bluetoothctl exited with code 1 Aug 31 18:21:13 volumio bluetoothd[810]: Adv Monitor app :1.123 disconnected from D-Bus Aug 31 18:21:13 volumio volumio[1202]: info: VolumeController::SetAlsaVolume75 Aug 31 18:21:13 volumio volumio[1202]: info: CoreStateMachine::pushState Aug 31 18:21:13 volumio volumio[1202]: info: CorePlayQueue::getTrack 2 Aug 31 18:21:13 volumio volumio[1202]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:21:13 volumio volumio[1202]: info: CoreCommandRouter::volumioPushState Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::volumioNext Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::next Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::stop Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::stPlaybackTimer Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::updateTrackBlock Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrackBlock Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 2 Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::volumioPushState Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::serviceStop Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 2 Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::serviceStop Aug 31 18:21:25 volumio volumio[1202]: info: ControllerMpd::stop Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 18:21:25 volumio volumio[1202]: info: Aug 31 18:21:25 volumio volumio[1202]: ---------------------------- MPD announces state update: player Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand stop took 16 milliseconds Aug 31 18:21:25 volumio volumio[1202]: info: ControllerMpd::getState Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand status Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::play index undefined Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::startPlaybackTimer Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::clearAddPlayTracks USB/MUSIC/.Trashes/501/The Beatles/The Beatles - Sgt. Pepper’s Lonely Hearts Club Band/04 - Getting Better.flac Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::updateTrackBlock Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrackBlock Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand status took 5 milliseconds Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand stop took 4 milliseconds Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::parseState Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand clear Aug 31 18:21:25 volumio volumio[1202]: info: Aug 31 18:21:25 volumio volumio[1202]: ---------------------------- MPD announces system playlist update Aug 31 18:21:25 volumio volumio[1202]: info: Ignoring MPD Status Update Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand playlistinfo took 3 milliseconds Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand clear took 3 milliseconds Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::parseTrackInfo Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand add "USB/MUSIC/.Trashes/501/The Beatles/The Beatles - Sgt. Pepper’s Lonely Hearts Club Band/04 - Getting Better.flac" Aug 31 18:21:25 volumio volumio[1202]: info: ControllerMpd::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::servicePushState Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::volumioPushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Lucy In The Sky With Diamonds","artist":"The Beatles","album":"Sgt. Pepper's Lonely Hearts Club Band","uri":"USB/MUSIC/.Trashes/501/The Beatles/The Beatles - Sgt. Pepper’s Lonely Hearts Club Band/03 - Lucy In The Sky With Diamonds.flac","trackType":"flac"} Aug 31 18:21:25 volumio volumio[1202]: verbose: CURRENT POSITION 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::syncState stateService stop Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::syncState currentStatus stop Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::volumioPushState Aug 31 18:21:25 volumio volumio[1202]: info: No code Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::volumioPushState Aug 31 18:21:25 volumio volumio[1202]: info: ------------------------------ 42ms Aug 31 18:21:25 volumio volumio[1202]: error: updateQueue error: null Aug 31 18:21:25 volumio volumio[1202]: info: Aug 31 18:21:25 volumio volumio[1202]: ---------------------------- MPD announces system playlist update Aug 31 18:21:25 volumio volumio[1202]: info: Ignoring MPD Status Update Aug 31 18:21:25 volumio volumio[1202]: info: ------------------------------ 36ms Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand add "USB/MUSIC/.Trashes/501/The Beatles/The Beatles - Sgt. Pepper’s Lonely Hearts Club Band/04 - Getting Better.flac" took 34 milliseconds Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand play Aug 31 18:21:25 volumio volumio[1202]: info: Aug 31 18:21:25 volumio volumio[1202]: ---------------------------- MPD announces state update: player Aug 31 18:21:25 volumio volumio[1202]: info: ------------------------------ 28ms Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand play took 28 milliseconds Aug 31 18:21:25 volumio volumio[1202]: info: ControllerMpd::getState Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand status Aug 31 18:21:25 volumio volumio[1202]: info: Aug 31 18:21:25 volumio volumio[1202]: ---------------------------- MPD announces state update: player Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand status took 71 milliseconds Aug 31 18:21:25 volumio volumio[1202]: info: ControllerMpd::getState Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand status Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::parseState Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand status took 4 milliseconds Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand playlistinfo took 4 milliseconds Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::parseState Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::parseTrackInfo Aug 31 18:21:25 volumio volumio[1202]: info: ControllerMpd::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::servicePushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":168,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Getting Better","artist":"The Beatles","album":"Sgt. Pepper's Lonely Hearts Club Band","uri":"USB/MUSIC/.Trashes/501/The Beatles/The Beatles - Sgt. Pepper’s Lonely Hearts Club Band/04 - Getting Better.flac","trackType":"flac"} Aug 31 18:21:25 volumio volumio[1202]: verbose: CURRENT POSITION 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::syncState stateService play Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::syncState currentStatus stop Aug 31 18:21:25 volumio volumio[1202]: info: ------------------------------ 82ms Aug 31 18:21:25 volumio volumio[1202]: info: sendMpdCommand playlistinfo took 5 milliseconds Aug 31 18:21:25 volumio volumio[1202]: verbose: ControllerMpd::parseTrackInfo Aug 31 18:21:25 volumio volumio[1202]: info: ControllerMpd::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::servicePushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: verbose: STATE SERVICE {"status":"play","position":0,"seek":994,"duration":168,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2655 Kbps","isStreaming":false,"title":"Getting Better","artist":"The Beatles","album":"Sgt. Pepper's Lonely Hearts Club Band","uri":"USB/MUSIC/.Trashes/501/The Beatles/The Beatles - Sgt. Pepper’s Lonely Hearts Club Band/04 - Getting Better.flac","trackType":"flac"} Aug 31 18:21:25 volumio volumio[1202]: verbose: CURRENT POSITION 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::syncState stateService play Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::syncState currentStatus play Aug 31 18:21:25 volumio volumio[1202]: info: Received an update from plugin. extracting info from payload Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::volumioPushState Aug 31 18:21:25 volumio volumio[1202]: info: CoreStateMachine::pushState Aug 31 18:21:25 volumio volumio[1202]: info: CorePlayQueue::getTrack 3 Aug 31 18:21:25 volumio volumio[1202]: info: CoreCommandRouter::volumioPushState Aug 31 18:21:25 volumio volumio[1202]: info: ------------------------------ 33ms Aug 31 18:21:28 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.124 Aug 31 18:21:28 volumio bluetoothd[810]: Adv Monitor app :1.124 disconnected from D-Bus Aug 31 18:21:28 volumio volumio[1202]: info: [Wireless Output Manager][Bluetooth] Reconnecting preferred device 1C:D3:AF:4D:08:3B Aug 31 18:21:28 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.125 Aug 31 18:21:33 volumio bluetoothd[810]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 1C:D3:AF:4D:08:3B: Host is down (112) Aug 31 18:21:33 volumio volumio[1202]: warn: [Wireless Output Manager][Bluetooth] Preferred speaker is unavailable: bluetoothctl exited with code 1 Aug 31 18:21:33 volumio bluetoothd[810]: Adv Monitor app :1.125 disconnected from D-Bus Aug 31 18:21:40 volumio volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 18:21:40 volumio volumio[1202]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 31 18:21:43 volumio volumio[1202]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 18:21:43 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.126 Aug 31 18:21:43 volumio bluetoothd[810]: Adv Monitor app :1.126 disconnected from D-Bus Aug 31 18:21:43 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.127 Aug 31 18:21:43 volumio bluetoothd[810]: Adv Monitor app :1.127 disconnected from D-Bus Aug 31 18:21:48 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.128 Aug 31 18:21:48 volumio bluetoothd[810]: Adv Monitor app :1.128 disconnected from D-Bus Aug 31 18:21:48 volumio volumio[1202]: info: [Wireless Output Manager][Bluetooth] Reconnecting preferred device 1C:D3:AF:4D:08:3B Aug 31 18:21:48 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.129 Aug 31 18:21:54 volumio bluetoothd[810]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 1C:D3:AF:4D:08:3B: Host is down (112) Aug 31 18:21:54 volumio bluetoothd[810]: Adv Monitor app :1.129 disconnected from D-Bus Aug 31 18:21:54 volumio volumio[1202]: warn: [Wireless Output Manager][Bluetooth] Preferred speaker is unavailable: bluetoothctl exited with code 1 Aug 31 18:21:56 volumio volumio[1202]: info: CALLMETHOD: system_hardware wireless_output_manager connectDevice Aug 31 18:21:56 volumio volumio[1202]: info: CoreCommandRouter::executeOnPlugin: wireless_output_manager , connectDevice Aug 31 18:21:56 volumio volumio[1202]: info: [Wireless Output Manager][Bluetooth] Connecting 1C:D3:AF:4D:08:3B Aug 31 18:21:56 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.130 Aug 31 18:21:56 volumio bluetoothd[810]: Adv Monitor app :1.130 disconnected from D-Bus Aug 31 18:21:56 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.131 Aug 31 18:21:56 volumio bluetoothd[810]: Adv Monitor app :1.131 disconnected from D-Bus Aug 31 18:21:56 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.132 Aug 31 18:21:56 volumio bluetoothd[810]: Adv Monitor app :1.132 disconnected from D-Bus Aug 31 18:21:56 volumio bluetoothd[810]: Path / reserved for Adv Monitor app :1.133 Aug 31 18:22:01 volumio bluetoothd[810]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 1C:D3:AF:4D:08:3B: Host is down (112) Aug 31 18:22:01 volumio bluetoothd[810]: Adv Monitor app :1.133 disconnected from D-Bus Aug 31 18:22:01 volumio volumio[1202]: error: [Wireless Output Manager][Bluetooth] Connecting 1C:D3:AF:4D:08:3B failed: bluetoothctl exited with code 1 Aug 31 18:22:01 volumio volumio[1202]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 18:22:01 volumio volumio[1202]: CommandError: bluetoothctl exited with code 1 Aug 31 18:22:01 volumio volumio[1202]: at ChildProcess. (/data/plugins/system_hardware/wireless_output_manager/lib/commandRunner.js:89:16) Aug 31 18:22:01 volumio volumio[1202]: at ChildProcess.emit (node:events:514:28) Aug 31 18:22:01 volumio volumio[1202]: at maybeClose (node:internal/child_process:1105:16) Aug 31 18:22:01 volumio volumio[1202]: at ChildProcess._handle.onexit (node:internal/child_process:305:5) { Aug 31 18:22:01 volumio volumio[1202]: result: { Aug 31 18:22:01 volumio volumio[1202]: command: 'bluetoothctl', Aug 31 18:22:01 volumio volumio[1202]: args: [ 'connect', '1C:D3:AF:4D:08:3B' ], Aug 31 18:22:01 volumio volumio[1202]: exitCode: 1, Aug 31 18:22:01 volumio volumio[1202]: signal: null, Aug 31 18:22:01 volumio volumio[1202]: stdout: 'Attempting to connect to 1C:D3:AF:4D:08:3B\n' + Aug 31 18:22:01 volumio volumio[1202]: '[\x1B[0;92mNEW\x1B[0m] Media /org/bluez/hci0 \n' + Aug 31 18:22:01 volumio volumio[1202]: '\tSupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb\n' + Aug 31 18:22:01 volumio volumio[1202]: '\tSupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb\n' + Aug 31 18:22:01 volumio volumio[1202]: '\tSupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb\n' + Aug 31 18:22:01 volumio volumio[1202]: 'AdvertisementMonitor path registered\n' + Aug 31 18:22:01 volumio volumio[1202]: 'Failed to connect: org.bluez.Error.Failed br-connection-page-timeout', Aug 31 18:22:01 volumio volumio[1202]: stderr: '', Aug 31 18:22:01 volumio volumio[1202]: timedOut: false Aug 31 18:22:01 volumio volumio[1202]: } Aug 31 18:22:01 volumio volumio[1202]: } Aug 31 18:22:01 volumio volumio[1202]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 18:22:04 volumio sudo[3899]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 18:21' Aug 31 18:22:04 volumio sudo[3899]: 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"