bluetooth-lowenergyraspberry-pi3python-3.7pybluez

Broken Pipe During BLE Scan (RPi, Python 3.7)


I've got some Python 3.7 BLE scanning code which typically runs fantastic on a RPi3 device in production. However, recently I've seen devices* introduced into the environment that will crash the BLE Scanner in ways that I don't know how to prevent/detect.

*Note: A Windows 10 Lenovo laptop with Bluetooth chip Qualcomm Atheros QCA61x4 Bluetooth 4.1 can bring this code to its knees. I've also heard that folks running the above next to a BLE Beacon site also crash frequently.

The crash occurs during the pkt = my_sock.recv(255) command and the exception is a _bluetooth.error (32, 'Broken Pipe')

Here is a minimal code example below that demonstrates the problem:

import logging
import select
import struct
import sys
import time
from subprocess import check_output, STDOUT, CalledProcessError

import bluetooth._bluetooth as bluez

ROOT_LOGGER = logging.getLogger()
ROOT_LOGGER.setLevel(logging.DEBUG)
ROOT_LOGGER.addHandler(logging.NullHandler())

SYS_CTL_LOG_FMT = '%(filename)-28s [%(lineno)-4d] %(levelname)-7s %(message)s'
SYSCTL_HANDLER = logging.StreamHandler(sys.stdout)
SYSCTL_HANDLER.setLevel(logging.DEBUG)
SYSCTL_HANDLER.setFormatter(logging.Formatter(SYS_CTL_LOG_FMT))
ROOT_LOGGER.addHandler(SYSCTL_HANDLER)
logger = logging.getLogger(__name__)

DEV_ID = 0
OGF_LE_CTL = 0x08
OCF_LE_SET_SCAN_PARAMETERS = 0x000B
OCF_LE_SET_SCAN_ENABLE = 0x000C
SCAN_RANDOM = 0x01
OWN_TYPE = SCAN_RANDOM
SCAN_TYPE = 0x01
INTERVAL = 0x10
WINDOW = 0x10
FILTER = 0x00  # all advertisements, not just whitelisted devices
ENABLE = 0x01


if __name__ == '__main__':
    while True:
        my_sock = bluez.hci_open_dev(DEV_ID)
        my_sock.settimeout(30.0)

        cmd_pkt = struct.pack("<BBBBBBB", SCAN_TYPE, 0x0, INTERVAL, 0x0, WINDOW, OWN_TYPE, FILTER)
        bluez.hci_send_cmd(my_sock, OGF_LE_CTL, OCF_LE_SET_SCAN_PARAMETERS, cmd_pkt)

        cmd_pkt = struct.pack("<BB", ENABLE, 0x00)
        bluez.hci_send_cmd(my_sock, OGF_LE_CTL, OCF_LE_SET_SCAN_ENABLE, cmd_pkt)

        flt = bluez.hci_filter_new()
        bluez.hci_filter_all_events(flt)
        bluez.hci_filter_set_ptype(flt, bluez.HCI_EVENT_PKT)
        my_sock.setsockopt(bluez.SOL_HCI, bluez.HCI_FILTER, flt)
        try:
            packets_received = 0
            while True:
                ready_to_read, ready_to_write, in_error = select.select([my_sock, ], [my_sock, ], [my_sock, ], 5)
                if len(ready_to_read) == 0:
                    time.sleep(0.001)
                    continue
                try:
                    pkt = my_sock.recv(255)
                except bluez.error as exc_data:
                    logger.error(f'Received a _bluetooth.error while trying to read. Aborting: {exc_data}')
                    raise
                packets_received += 1
                ptype, event, plen = struct.unpack("BBB", pkt[:3])
                logger.info(f'{packets_received} {ptype}, {event}, {plen}')

        except bluez.error:
            my_sock.close()
            while True:
                # this loops until hciconfig is able to successfully restart
                try:
                    check_output('sudo hciconfig hci0 up', shell=True, stderr=STDOUT)
                except CalledProcessError as exc_data:
                    logger.warning(f'{type(exc_data)}: {exc_data}')
                    continue
                time.sleep(1)
                break

Output looks like this:

pi@raspberrypi:~/my_test $ sudo python3 distilled_test.py
distilled_test.py            [63  ] INFO    1 4, 14, 4
distilled_test.py            [63  ] INFO    2 4, 14, 4
distilled_test.py            [63  ] INFO    3 4, 62, 27
distilled_test.py            [63  ] INFO    4 4, 62, 26
distilled_test.py            [63  ] INFO    5 4, 62, 12
distilled_test.py            [63  ] INFO    6 4, 62, 31
distilled_test.py            [63  ] INFO    7 4, 62, 31
distilled_test.py            [63  ] INFO    8 4, 62, 31
distilled_test.py            [63  ] INFO    9 4, 62, 31
distilled_test.py            [63  ] INFO    10 4, 62, 31
distilled_test.py            [63  ] INFO    11 4, 62, 31
distilled_test.py            [63  ] INFO    12 4, 62, 31
distilled_test.py            [63  ] INFO    13 4, 62, 31
distilled_test.py            [63  ] INFO    14 4, 62, 31
distilled_test.py            [63  ] INFO    15 4, 62, 31
distilled_test.py            [63  ] INFO    16 4, 62, 31
distilled_test.py            [63  ] INFO    17 4, 62, 31
distilled_test.py            [63  ] INFO    18 4, 62, 31
distilled_test.py            [63  ] INFO    19 4, 62, 31
distilled_test.py            [63  ] INFO    20 4, 62, 31
distilled_test.py            [63  ] INFO    21 4, 62, 31
distilled_test.py            [63  ] INFO    22 4, 62, 31
distilled_test.py            [59  ] ERROR   Received a _bluetooth.error while trying to read. Aborting: (32, 'Broken pipe')
distilled_test.py            [72  ] WARNING <class 'subprocess.CalledProcessError'>: Command 'sudo hciconfig hci0 up' returned non-zero exit status 1.
distilled_test.py            [72  ] WARNING <class 'subprocess.CalledProcessError'>: Command 'sudo hciconfig hci0 up' returned non-zero exit status 1.
distilled_test.py            [72  ] WARNING <class 'subprocess.CalledProcessError'>: Command 'sudo hciconfig hci0 up' returned non-zero exit status 1.
distilled_test.py            [72  ] WARNING <class 'subprocess.CalledProcessError'>: Command 'sudo hciconfig hci0 up' returned non-zero exit status 1.
distilled_test.py            [72  ] WARNING <class 'subprocess.CalledProcessError'>: Command 'sudo hciconfig hci0 up' returned non-zero exit status 1.
distilled_test.py            [63  ] INFO    1 4, 14, 4
distilled_test.py            [63  ] INFO    2 4, 14, 4
distilled_test.py            [63  ] INFO    3 4, 62, 27
distilled_test.py            [63  ] INFO    4 4, 62, 26
distilled_test.py            [63  ] INFO    5 4, 62, 40
distilled_test.py            [63  ] INFO    6 4, 62, 39

My theory is that the new BLE Broadcasting device is flooding the RPi with Bluetooth traffic to the point where I'm not ingesting it fast enough and the Bluetooth service closes the socket. Advice?

Raspbian Buster Lite bluez-5.52.tar.xz gattlib-0.20150805 pybluez-0.23 Python 3.7.3

I should also note that this Lenovo/Qualcomm laptop Bluetooth advertising is enough to cause my go-to Android app nRF Connect to repeatedly cycle Bluetooth. Though I realize I can't prevent the Lenovo/Qualcomm from being naughty, I still feel like I need to protect my app from crashing due to the Bluetooth noise.


Solution

  • So, as it turns out, the broken pipe really does in-fact mean broken pipe... imagine that.

    I wired up the project to a RPi4 and was able to see the code processing Bluetooth messages fast enough to keep up. As I had supposed in the original question, the RPi3 code was not keeping up with the rate that the Bluetooth chip was receiving messages and at some point, some sort of buffer/pipe/queue filled up and the Bluetooth (Bluez, probably) broke the pipe.