[BUG] [PYTHON] BLE Scan crash

[mingjiansi]

Reproduction steps

Initiate DiscoverySync or DiscoveryAsync will cause entire process to crash with the following message
[1682519165.322591][1219598:1219598] CHIP:DL: Chip stack locking error at 'src/system/SystemLayerImplSelect.cpp:125'. Code is unsafe/racy
[1682519165.322610][1219598:1219598] CHIP:-: chipDie chipDie chipDie

Issue can be traced to assertChipStackLockedByCurrentThread(); to the beginning of LayerSelect::StartTimer and LayerSelect::CancelTimer

Bug prevalence

Everytime

GitHub hash of the SDK that was being used

980a1a1

Platform

python

Platform Version(s)

No response

Anything else?

Issue can be traced to assertChipStackLockedByCurrentThread(); to the beginning of LayerSelect::StartTimer and LayerSelect::CancelTimer

[bzbarsky-apple]

@mingjiansi What's the stack to the failing assert?

[bzbarsky-apple]

And I thought this was fixed in #26200 ?

[mingjiansi]

@bzbarsky-apple my use case might be a little different than usual. What i have done is to use the build_python.sh script to compile into whl file then directly use the whl package in code. This allows me to test light bulbs and plugs in a more controlled and automated fashion. However, in this use case there are two different failures.

1. when in python script directly import and invoke chip.ble.DiscoverySync or the async version. the stack immediately crashes. After i commented out the assertChipStackLockedByCurrentThread(); from the StartTimer and CancelTimer, failure no longer occur. At this point, I have no idea how I can get trace the stack for this issue.
2. In the python interface, there is no ScanError callback, and from what I can tell the C++ interface is expecting that, so whenever a BLE scan error occurs, stack fails again. I have added a default handler for error that seems to do the trick.

[mingjiansi]

console screen for the error is following:

[1682610262.862360][872234:872234] CHIP:CTL: Setting attestation nonce to random value
[1682610262.863067][872234:872234] CHIP:CTL: Setting CSR nonce to random value
[1682610262.863810][872234:872234] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-pMqW7J)
[1682610262.863967][872234:872234] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1682610262.863977][872234:872234] CHIP:DL: NVS set: chip-counters/reboot-count = 9 (0x9)
[1682610262.864598][872234:872234] CHIP:DL: Got Ethernet interface: enx5cff35d579d4
[1682610262.864916][872234:872234] CHIP:DL: Found the primary Ethernet interface:enx5cff35d579d4
[1682610262.864956][872234:872234] CHIP:DL: Got WiFi interface: wlp45s0
[1682610262.866640][872234:872234] CHIP:DL: Found the primary WiFi interface:wlp45s0
Initializing persistent storage from file: ./chip-ge-stacks.bin
Loading configuration from ./chip-ge-stacks.bin...
[1682610262.867335][872234:872234] CHIP:TS: Last Known Good Time: 2023-04-27T11:42:08
[1682610262.867666][872234:872234] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xFEB3387C2067A0B3, FabricId 0x000000000000000F, NodeId 0x0000000000001F40, VendorId 0x1339
[1682610262.868030][872234:872234] CHIP:ZCL: Using ZAP configuration...
[1682610262.869115][872234:872234] CHIP:DL: Avahi client registered
Loading certificate authorities from storage...
New CertificateAuthority at index 1
Loading fabric admins from storage...
New FabricAdmin: FabricId: 0x000000000000000F, VendorId = 0x1339
Allocating new controller with CaIndex: 1, FabricId: 0x000000000000000F, NodeId: 0x0000000000001F40, CatTags: []
[1682610262.907842][872234:872240] CHIP:CTL: Setting attestation nonce to random value
[1682610262.907903][872234:872240] CHIP:CTL: Setting CSR nonce to random value
[1682610262.907922][872234:872240] CHIP:SPT: Using device attestation PAA trust store path /home/ubuntu/trust-cert/.
[1682610262.908314][872234:872240] CHIP:CTL: Generating NOC
[1682610262.908752][872234:872240] CHIP:FP: Validating NOC chain
[1682610262.909252][872234:872240] CHIP:FP: NOC chain validation successful
[1682610262.909298][872234:872240] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x0000000000001F40
[1682610262.909305][872234:872240] CHIP:TS: Last Known Good Time: 2023-04-27T11:42:08
[1682610262.909309][872234:872240] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1682610262.909314][872234:872240] CHIP:TS: Retaining current Last Known Good Time
[1682610262.909585][872234:872240] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1682610262.909748][872234:872240] CHIP:TS: Committing Last Known Good Time to storage: 2023-04-27T11:42:08
[1682610262.909911][872234:872240] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x000000000000000F (Compressed Fabric ID: FEB3387C2067A0B3)
[1682610262.909916][872234:872240] CHIP:CTL: *** Missing DeviceAttestationVerifier configuration at DeviceCommissioner init: using global default, consider passing one in CommissionerInitParams.
[1682610262.909964][872234:872240] CHIP:SPT: Setting up group data for Fabric Index 1 with Compressed Fabric ID:
[{'fabricID': 15, 'devices': [{'nodeID': 15, 'productID': 89}, {'nodeID': 16, 'productID': 89}]}]
[1682610262.919278][872234:872239] CHIP:BLE: BLE removing known devices.
[1682610262.919795][872234:872239] CHIP:BLE: BLE initiating scan.
[1682610263.042385][872234:872234] CHIP:DL: Chip stack locking error at 'src/system/SystemLayerImplSelect.cpp:125'. Code is unsafe/racy
[1682610263.042400][872234:872234] CHIP:-: chipDie chipDie chipDie
Aborted

[bzbarsky-apple]

At this point, I have no idea how I can get trace the stack for this issue.

Run python under a debugger, wait for the crash, then look at the stack.

[bzbarsky-apple]

That said, src/platform/Linux/bluez/ChipDeviceScanner.cpp has StartTimer and CancelTimer calls that might be happening on the wrong threads and should probably take the stack lock. @mingjiansi can you test whether that fixes your issue, please?

[mingjiansi]

That said, src/platform/Linux/bluez/ChipDeviceScanner.cpp has StartTimer and CancelTimer calls that might be happening on the wrong threads and should probably take the stack lock. @mingjiansi can you test whether that fixes your issue, please?

this unfortunately did not fix the issue. the crash just happened in src/platform/Linux/bluez/ChipDeviceScanner.cpp instead.

[mingjiansi]

At this point, I have no idea how I can get trace the stack for this issue.

Run python under a debugger, wait for the crash, then look at the stack.

I attempted using pdb and set_trace. since the error happened in the c++ library, there was nothing from python side

[bzbarsky-apple]

 this unfortunately did not fix the issue. the crash just happened in src/platform/Linux/bluez/ChipDeviceScanner.cpp instead.

I'm not following. I suggested adding the appropriate locks to src/platform/Linux/bluez/ChipDeviceScanner.cpp. Did you try doing that?

[bzbarsky-apple]

I attempted using pdb and set_trace. since the error happened in the c++ library, there was nothing from python side

You'd want to use gdb attached to the python process. But again: I suspect that fixing src/platform/Linux/bluez/ChipDeviceScanner.cpp would help. It might not be the only thing that needs fixing, of course.

[tehampson]

Hi @mingjiansi, can you tell me the exact chip-repl command you are running. Right now when I run chip-repl I do the following 2 command:
import chip.ble
asdf = chip.ble.DiscoverSync(timeoutMs=5000)

I get a generator. If I try doing something like: for x in asdf: print(x) I get

2023-05-02 18:21:06 thampson-boreal.c.googlers.com chip.DL[1086138] ERROR Failed to get DBUS object manager for listing adapters.
2023-05-02 18:21:06 thampson-boreal.c.googlers.com chip.DL[1086138] ERROR DBus error: Error calling StartServiceByName for org.bluez: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)

If you have a way to reproduce, normally the way have debugged with GDB I have done gdb --args python3 .environment/pigweed-venv/bin/chip-repl. It will compain about not it cannot find symbols for python3. That is fine, just type r run, reproduce the issue and typically you can get the stack trace

[mingjiansi]

@tehampson As I mentioned above, this error occurred when I ran a python file I wrote outside of repl. for example something like the following.

import argparse
import asyncio
import atexit
import builtins
import datetime
import json
import logging
import random
import time
import math

import chip.CertificateAuthority
import chip.discovery
import chip.FabricAdmin
import chip.logging
import chip.native
import chip.ble
import chip.setup_payload
import coloredlogs
from chip import discovery
from chip.ChipDeviceCtrl import ChipDeviceController
from chip.ChipStack import *


def chipStartUp(chipFilePath: str):
    chip.native.Init()

    chipStack = ChipStack(persistentStoragePath=chipFilePath,
                          bluetoothAdapter=None,
                          enableServerInteractions=False)

    certificateAuthorityManager = chip.CertificateAuthority.CertificateAuthorityManager(chipStack,
                                                                                        chipStack.GetStorageManager())

    certificateAuthorityManager.LoadAuthoritiesFromStorage()
    vendor = 4921
    fabric = 15

    if (len(certificateAuthorityManager.activeCaList) == 0):
        ca = certificateAuthorityManager.NewCertificateAuthority()
        ca.NewFabricAdmin(vendorId=vendor, fabricId=fabric)
    elif (len(certificateAuthorityManager.activeCaList[0].adminList) == 0):
        certificateAuthorityManager.activeCaList[0].NewFabricAdmin(vendorId=vendor, fabricId=fabric)

    caList = certificateAuthorityManager.activeCaList

    certPath = '/home/ubuntu/trust-cert/'

    devCtrl = caList[0].adminList[0].NewController(
        10, certPath, False
    )

    builtins.devCtrl = devCtrl
    builtins.certificateAuthorityManager = certificateAuthorityManager


if __name__ == '__main__':
    chipStartUp('./chip-ge-stacks.bin')

    bleValues = chip.ble.DiscoverSync(timeoutMs=5000)
    for v in bleValues:
        print(v)
'''        

[tehampson]

Hm... When I am doing something similar in the chip-repl interactive shell I am not hitting any crash. I get a timeout but that is it.

@mingjiansi did you try doing something like gdb --args python3 yourscript.py followed by r in the gdb shell?