Skip to content

Runs for X minutes and then dies contd... (bluetooth stack instability?) #14

Open
@trinitronx

Description

@trinitronx

I believe the issue described in #4 is still happening as of latest Raspbian GNU/Linux 9 (stretch) + bluetooth stack components:

$ dpkg -l | grep -i blue
ii  bluealsa                              0.9                                       armhf        Bluetooth ALSA Audio backend
ii  bluej                                 3.1.7b                                    all          A simple but powerful Java IDE.
ii  bluez                                 5.43-2+rpt2+deb9u2                        armhf        Bluetooth tools and daemons
ii  bluez-firmware                        1.2-3+rpt7                                all          Firmware for Bluetooth devices
ii  libbluetooth3:armhf                   5.43-2+rpt2+deb9u2                        armhf        Library to use the BlueZ Linux Bluetooth stack
ii  lxplug-bluetooth                      0.6                                       armhf        Bluetooth plugin for lxpanel
ii  pi-bluetooth                          0.1.10                                    all          Raspberry Pi 3 bluetooth

$ bluetoothd -v 
5.43

Based on my experiences and experimentation, it appears that the issue is in the underlying code powering this script either bluepy, bluez, broadcom drivers, or some combination? Some searching online shows many others are having similar Bluetooth stack instability on Raspbian.

I've been trying to get this code running as a long-term solution for reading and sending metrics to Graphite. I should note that so far I've been prevented from running the script as-is on Python 2.7 because I was unable to install bluepy via pip package. However, I was able to get the Python3 version from piwheels so I could move forward just converting all the print statements in this script to use parentheses print().

After testing out the script on the host, I found that I had to add kernel capabilities to the bluepy_helper binary. This binary is installed as part of bluepy and must have been why the Python 2.7 version from pip could not install a wheel or compile on the Raspberry Pi.

$ sudo setcap 'cap_net_raw,cap_net_admin+eip'  /home/pi/.local/lib/python3.5/site-packages/bluepy/bluepy-helper

$ sudo getcap /home/pi/.local/lib/python3.5/site-packages/bluepy/bluepy-helper
/home/pi/.local/lib/python3.5/site-packages/bluepy/bluepy-helper = cap_net_admin,cap_net_raw+eip

After running the script for a while, I've seen various ways in which it fails or eventually hangs. This always seems to happen after some varying period of time. I've tried also adding a SystemD unit which is supposed to restart the process and reset the hci0 device, yet eventually each time the code hangs. I'm collecting the various exceptions in logs to see how to handle them.

SystemD Unit:

[Unit]
Description=Airthings WavePlus Reader (Send to Graphite)
Documentation=https://www.airthings.com/blog/wave-plus-raspberry-pi
#BindsTo=sys-subsystem-net-devices-eth0.device sys-subsystem-net-devices-wlan0.device
After=network-online.target bluetooth.target dbus-org.bluez.service sys-subsystem-net-devices-eth0.device sys-subsystem-bluetooth-devices-hci0.device [email protected] sys-subsystem-net-devices-wlan0.device ifup
Wants=network-online.target bluetooth.target [email protected] dhcpcd.service wpa_supplicant.service

[Service]
Type=simple
EnvironmentFile=/etc/default/waveplus-reader
ExecStartPre=-/bin/sh -c '/bin/echo power on | /usr/bin/bluetoothctl'
ExecStartPre=-/bin/hciconfig up hci0
User=pi
ExecStart=/usr/bin/python3 -u /home/pi/src/pub/waveplus-reader/read_waveplus.py $WAVEPLUS_SN $WAVEPLUS_SAMPLE_PERIOD
ExecStopPost=-/bin/hciconfig down hci0
ExecStopPost=-/bin/sh -c '/bin/echo power off | /usr/bin/bluetoothctl'
Restart=always
RestartSec=3
AmbientCapabilities=CAP_NET_ADMIN CAP_NET_RAW

[Install]
WantedBy=multi-user.target

Error examples & strace debugging:

Jun 25 11:29:43 raspberrypi python3[14770]: ERROR: <class 'bluepy.btle.BTLEManagementError'>
Jun 25 11:29:43 raspberrypi python3[14770]: Failed to execute management command 'scanend' (code: 11, error: Rejected)
Jun 25 11:29:43 raspberrypi python3[14770]: ERROR: <class 'bluepy.btle.BTLEManagementError'>
Jun 25 11:29:43 raspberrypi python3[14770]: Failed to execute management command 'scanend' (code: 11, error: Rejected)

I tried getting an strace after finding that bluepy-helper had hung:

Jun 26 09:00:16 raspberrypi python3[857]: ERROR: <class 'bluepy.btle.BTLEGattError'>
Jun 26 09:00:16 raspberrypi python3[857]: Bluetooth command failed (code: 14, error: Request attribute has encountered an unlikely error)
Jun 26 09:00:18 raspberrypi python3[857]: │     47.0 %rH │     31 Bq/m3 │      0 Bq/m3 │   19.83 degC │    837.1 hPa │    560.0 ppm │     71.0 ppb │
Jun 26 09:01:22 raspberrypi python3[857]: │     47.0 %rH │     31 Bq/m3 │      0 Bq/m3 │   19.83 degC │    837.1 hPa │    560.0 ppm │     71.0 ppb │
Jun 26 09:02:25 raspberrypi python3[857]: │     47.0 %rH │     31 Bq/m3 │      0 Bq/m3 │   19.83 degC │    837.1 hPa │    560.0 ppm │     71.0 ppb │
Jun 26 09:03:28 raspberrypi python3[857]: │     47.0 %rH │     31 Bq/m3 │      0 Bq/m3 │   19.83 degC │    837.1 hPa │    560.0 ppm │     71.0 ppb │
Jun 26 09:04:32 raspberrypi python3[857]: │     47.0 %rH │     31 Bq/m3 │      0 Bq/m3 │   19.83 degC │    837.1 hPa │    560.0 ppm │     71.0 ppb │
Jun 26 09:05:35 raspberrypi python3[857]: │     47.0 %rH │     31 Bq/m3 │      0 Bq/m3 │   19.83 degC │    837.1 hPa │    567.0 ppm │     84.0 ppb │
Jun 26 09:06:38 raspberrypi python3[857]: │     47.0 %rH │     31 Bq/m3 │      0 Bq/m3 │   19.83 degC │    837.1 hPa │    567.0 ppm │     84.0 ppb │
Jun 26 09:07:41 raspberrypi python3[857]: ERROR: <class 'bluepy.btle.BTLEGattError'>
Jun 26 09:07:41 raspberrypi python3[857]: Bluetooth command failed (code: 10, error: No attribute found within the given range)



pi@raspberrypi:~ $ sudo systemctl status waveplus-reader
● waveplus-reader.service - Airthings WavePlus Reader (Send to Graphite)
   Loaded: loaded (/etc/systemd/system/waveplus-reader.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2019-06-26 08:27:32 MDT; 13h ago
     Docs: https://www.airthings.com/blog/wave-plus-raspberry-pi
  Process: 854 ExecStartPre=/bin/hciconfig up hci0 (code=exited, status=0/SUCCESS)
  Process: 826 ExecStartPre=/bin/sh -c /bin/echo power on | /usr/bin/bluetoothctl (code=exited, status=0/SUCCESS)
 Main PID: 857 (python3)
    Tasks: 2 (limit: 4915)
   Memory: 10.5M
      CPU: 12h 11min 7.354s
   CGroup: /system.slice/waveplus-reader.service
           ├─ 857 /usr/bin/python3 -u /home/pi/src/pub/waveplus-reader/read_waveplus.py 2930006452 60
           └─8906 /home/pi/.local/lib/python3.5/site-packages/bluepy/bluepy-helper

$ sudo strace -p 8906

## same polling event repeated... infinite loop?
[...SNIP...]
poll([{fd=0, events=POLLIN}, {fd=3, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=0}], 4, -1) = 1 ([{fd=5, revents=POLLNVAL}])
poll([{fd=0, events=POLLIN}, {fd=3, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=0}], 4, -1) = 1 ([{fd=5, revents=POLLNVAL}])
poll([{fd=0, events=POLLIN}, {fd=3, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=0}], 4, -1) = 1 ([{fd=5, revents=POLLNVAL}])
poll([{fd=0, events=POLLIN}, {fd=3, events=POLLIN}, {fd=4, events=POLLIN}, {fd=5, events=0}], 4, -1) = 1 ([{fd=5, revents=POLLNVAL}])
[...SNIP...]

$ sudo strace -p 857
strace: Process 857 attached
read(6,


# That's it... nothing else.  It's waiting on bluepy-helper?
# I killed the stuck bluepy-helper and got this:

Jun 26 21:51:14 raspberrypi python3[857]: ERROR: <class 'bluepy.btle.BTLEInternalError'>
Jun 26 21:51:14 raspberrypi python3[857]: Helper exited
Jun 26 21:51:14 raspberrypi python3[857]: ERROR: <class 'BrokenPipeError'>
Jun 26 21:51:14 raspberrypi python3[857]: [Errno 32] Broken pipe
Jun 26 21:51:14 raspberrypi python3[857]: ERROR: <class 'BrokenPipeError'>
Jun 26 21:51:14 raspberrypi python3[857]: [Errno 32] Broken pipe
Jun 26 21:51:14 raspberrypi python3[857]: ERROR: <class 'BrokenPipeError'>
Jun 26 21:51:14 raspberrypi python3[857]: [Errno 32] Broken pipe
Jun 26 21:51:14 raspberrypi python3[857]: ERROR: <class 'BrokenPipeError'>
Jun 26 21:51:14 raspberrypi python3[857]: [Errno 32] Broken pipe
Jun 26 21:51:14 raspberrypi python3[857]: ERROR: <class 'BrokenPipeError'>
[...SNIP...]

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions