Could not determine BlueZ version, bluetoothctl not available, assuming 5.51+

[jeffsf]

• bleak version: 0.19.5
• Python version: 3.11.1
• Operating System:

(pyde1-devel) jeff@pi-walnut:~ $ cat /etc/os-release 
PRETTY_NAME="Debian GNU/Linux 11 (bullseye)"
NAME="Debian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"
VERSION_CODENAME=bullseye
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

Running on Raspberry Pi 3B+

• BlueZ version (bluetoothctl -v) in case of Linux: 5.55

Description

When bleak initializes, it appears to make a call to get the BlueZ version. Although the user under which the process is running is a member of the bluetooth group and can run bluetoothctl from the command line as well as from within Python, the call apparently fails.

In examining the code at bleak/backends/bluezdbus/version.py, the seemingly relevant function was tested on the target system with the target user and venv.

import bleak.backends.bluezdbus.version as bv

import pytest

@pytest.mark.asyncio
async def test_version():
    version_output  = await bv._get_bluetoothctl_version()
    assert version_output
    major, minor = tuple(map(int, version_output.groups()))
    assert major == 5
    assert minor == 55

Running within a complex program under the same user and venv, it fails with the following logs

2022-12-27 20:33:41,875 DEBUG [Controller] root.bleak.backends.bluezdbus.client: Connecting to device @ 00:A0:50:E2:F6:49
2022-12-27 20:33:41,914 INFO [Controller] root.asyncio: <_UnixSubprocessTransport pid=14666 running stdout=<_UnixReadPipeTransport fd=17 polling>> exited with return code 0
2022-12-27 20:33:41,917 INFO [Controller] root.asyncio: execute program 'bluetoothctl': <_UnixSubprocessTransport pid=14666 returncode=0 stdout=<_UnixReadPipeTransport closing fd=17 idle>>
2022-12-27 20:33:41,925 WARNING [Controller] root: Could not determine BlueZ version, bluetoothctl not available, assuming 5.51+

Any suggestions as how to diagnose this further?

[jeffsf]

I thought it might be that the client is running in a subprocess, but a quick check didn't provide any further insight

import asyncio
import multiprocessing
import os

import bleak.backends.bluezdbus.version as bv

async def subprocess_task():
    version_output  = await bv._get_bluetoothctl_version()
    if version_output:
        major, minor = tuple(map(int, version_output.groups()))
        print(major, minor)
    else:
        print("No version_output")
    await asyncio.sleep(1.0)

def subprocess_work():
    sploop = asyncio.new_event_loop()
    print(f"Inner loop: {sploop} {os.getpid()} {sploop._selector}")
    sploop.run_until_complete(subprocess_task())


if __name__ == '__main__':
    multiprocessing.set_start_method('spawn', force=True)
    loop = asyncio.new_event_loop()
    print(f"Outer loop: {loop} {os.getpid()} {loop._selector}")
    loop.run_until_complete(subprocess_task())
    p = multiprocessing.Process(target=subprocess_work)
    p.start()

Outer loop: <_UnixSelectorEventLoop running=False closed=False debug=False> 15151 <selectors.EpollSelector object at 0x7fa05bbe10>
5 55
Inner loop: <_UnixSelectorEventLoop running=False closed=False debug=False> 15155 <selectors.EpollSelector object at 0x7fb6506d50>
5 55

[dlech]

Maybe bluetoothctl is not in PATH in the failing case?

[jeffsf]

Just checked that, from within the process that is managing the bluetooth:

logger.info(f"UID: {os.getuid()} PATH: {os.environ['PATH']}")

2022-12-28 08:54:54,812 INFO [Controller] Controller: UID: 110 PATH: /usr/local/bin:/usr/bin:/bin:/usr/games

$ which bluetoothctl
/usr/bin/bluetoothctl
$ id 110
uid=110(pyde1) gid=114(pyde1) groups=114(pyde1),112(bluetooth)

There's also <_UnixSubprocessTransport pid=14666 running stdout=<_UnixReadPipeTransport fd=17 polling>> exited with return code 0 that suggests that something ran without error.

Once I have some more coffee, I'll try a wrapper at /usr/local/bin/bluetoothctl and see if that can give more insight.

[jeffsf]

Puzzling, as adding a wrapper "fixes" things.

After determining that the wrapper fixed the issue at /usr/local/bin, I moved to /usr/bin (the location of bluetoothctl).

There is a subtle difference in the log messages with closing fd=17 idle direct and was closed by peer with the wrapper.

Moved the executable to bluetoothctl.orig

Without the wrapper (failure):

2022-12-28 09:45:27,908 INFO [Controller] root.asyncio: <_UnixSubprocessTransport pid=19962 running stdout=<_UnixReadPipeTransport fd=17 polling>> exited with return code 0
2022-12-28 09:45:27,912 INFO [Controller] root.asyncio: execute program 'bluetoothctl': <_UnixSubprocessTransport pid=19962 returncode=0 stdout=<_UnixReadPipeTransport closing fd=17 idle>>
2022-12-28 09:45:27,919 WARNING [Controller] root: Could not determine BlueZ version, bluetoothctl not available, assuming 5.51+

With the wrapper (successful)

2022-12-28 09:50:16,714 INFO [Controller] root.asyncio: execute program 'bluetoothctl': <_UnixSubprocessTransport pid=20093 running stdout=<_UnixReadPipeTransport fd=17 polling>>
2022-12-28 09:50:16,719 INFO [Controller] root.asyncio: <_UnixReadPipeTransport fd=17 polling> was closed by peer
2022-12-28 09:50:16,726 INFO [Controller] root.asyncio: <_UnixSubprocessTransport pid=20093 running stdout=<_UnixReadPipeTransport closed fd=17 closed>> exited with return code 0

The wrapper:

/usr/bin $ cat bluetoothctl
#!/bin/sh
output=$(/usr/bin/bluetoothctl.orig "$@" 2>/tmp/bluetoothctl.stderr)
ev=$?
echo "$output" > /tmp/bluetoothctl.stdout
echo "$ev" > /tmp/bluetoothctl.ev
printf '%s' "$output"

The ownership and contents of the output files are as expected.
Interestingly with the wrapper, the name changes in the output. Looking into this further.

---

Two differences with the original wrapper were that bluetoothctl.orig was appearing instead of bluetoothctl and there was no line break at the end of the output. Changing these to get "the same" output does not change the "success" of the wrapper.

2022-12-28 10:20:27,561 INFO [Controller] root.asyncio: execute program 'bluetoothctl': <_UnixSubprocessTransport pid=20650 running stdout=<_UnixReadPipeTransport fd=17 polling>>
2022-12-28 10:20:27,566 INFO [Controller] root.asyncio: <_UnixReadPipeTransport fd=17 polling> was closed by peer
2022-12-28 10:20:27,576 INFO [Controller] root.asyncio: <_UnixSubprocessTransport pid=20650 running stdout=<_UnixReadPipeTransport closed fd=17 closed>> exited with return code 0

#!/bin/sh
output=$(/home/pyde1/bluetoothctl "$@" 2>/tmp/bluetoothctl.stderr)
ev=$?
echo "$output" > /tmp/bluetoothctl.stdout
echo "$ev" > /tmp/bluetoothctl.ev
# printf '%s' "$output"
echo "$output"

---

It looks to be something different between the call to a script and the call to the executable directly as just wrapping the executable in a script succeeds

#!/bin/sh
/home/pyde1/bluetoothctl "$@"

The earlier noted "idle" may be a red herring, as it is seen here as well (as well as the "closed by peer" variant).

2022-12-28 10:57:05,610 INFO [Controller] root.asyncio: <_UnixSubprocessTransport pid=21788 running stdout=<_UnixReadPipeTransport fd=17 polling>> exited with return code 0
2022-12-28 10:57:05,614 INFO [Controller] root.asyncio: execute program 'bluetoothctl': <_UnixSubprocessTransport pid=21788 returncode=0 stdout=<_UnixReadPipeTransport closing fd=17 idle>>

2022-12-28 10:59:18,555 INFO [Controller] root.asyncio: execute program 'bluetoothctl': <_UnixSubprocessTransport pid=21846 running stdout=<_UnixReadPipeTransport fd=17 polling>>
2022-12-28 10:59:18,561 INFO [Controller] root.asyncio: <_UnixReadPipeTransport fd=17 polling> was closed by peer
2022-12-28 10:59:18,568 INFO [Controller] root.asyncio: <_UnixSubprocessTransport pid=21846 running stdout=<_UnixReadPipeTransport closed fd=17 closed>> exited with return code 0

[jeffsf]

Seems to occur with Python 3.11.1, but not in 3.10.9 or 3.9.2

Edit: It does not seem to occur with 3.11.0

Maybe: python/cpython#100133

[jeffsf]

Resolved in 3.11-dev as installed by pyenv this evening.

Closing at this appears to be a Python issue