[MATTER] CHIP:DL: FAIL: NULL apEndpoint->mpAdapter in bluezObjectsSetup

[Jeffery]

Hi 

Referred to below link, installed OTBR and CHOIP-TOOL at RaspBerry Pi 4.

https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/protocols/matter/getting_started/testing/thread_one_otbr.html

On nrf52840 dongle acts as RCP and plugged in Pi USB port.

During pairing ble-thread, Pi will cancel the pairing and then close bluetooth as the error "CHIP:DL: FAIL: NULL apEndpoint->mpAdapter in bluezObjectsSetup".

I tried manual and Docker installation both. However, both failed at same error. Did you know the reason and how to fix the problem?

1. Log at Pi side during pairing

Fullscreen 2318.新文字文件 (2).txt Download

[1687931169.237647][1315:1315] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1687931169.248875][1315:1315] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_facto                                                     ry.ini
[1687931169.253489][1315:1315] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_confi                                                     g.ini
[1687931169.254395][1315:1315] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_count                                                     ers.ini
[1687931169.255890][1315:1315] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-3YtrEi)
[1687931169.256691][1315:1315] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1687931169.256771][1315:1315] CHIP:DL: NVS set: chip-counters/reboot-count = 111 (0x6F)
[1687931169.257735][1315:1315] CHIP:DL: Got Ethernet interface: eth0
[1687931169.258330][1315:1315] CHIP:DL: Found the primary Ethernet interface:eth0
[1687931169.258988][1315:1315] CHIP:DL: Got WiFi interface: wlan0
[1687931169.261450][1315:1315] CHIP:DL: Found the primary WiFi interface:wlan0
[1687931169.261535][1315:1315] CHIP:IN: UDP::Init bind&listen port=0
[1687931169.261740][1315:1315] CHIP:IN: UDP::Init bound to port=59592
[1687931169.261777][1315:1315] CHIP:IN: UDP::Init bind&listen port=0
[1687931169.261913][1315:1315] CHIP:IN: UDP::Init bound to port=40377
[1687931169.261945][1315:1315] CHIP:IN: BLEBase::Init - setting/overriding transport
[1687931169.261975][1315:1315] CHIP:IN: TransportMgr initialized
[1687931169.262057][1315:1315] CHIP:FP: Initializing FabricTable from persistent storage
[1687931169.274604][1315:1315] CHIP:TS: Last Known Good Time: 2023-06-01T08:25:29
[1687931169.275397][1315:1315] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed Fabric                                                     Id 0xBC3EE8D1A58AE9C3, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1687931169.292241][1315:1315] CHIP:ZCL: Using ZAP configuration...
[1687931169.301564][1315:1315] CHIP:DL: Avahi client registered
[1687931169.307652][1315:1315] CHIP:CTL: System State Initialized...
[1687931169.310056][1315:1315] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687931169.310146][1315:1315] CHIP:CTL: Setting attestation nonce to random value
[1687931169.310184][1315:1315] CHIP:CTL: Setting CSR nonce to random value
[1687931169.310510][1315:1317] CHIP:DL: CHIP task running
[1687931169.310720][1315:1317] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1687931169.312046][1315:1317] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687931169.312113][1315:1317] CHIP:CTL: Setting attestation nonce to random value
[1687931169.312153][1315:1317] CHIP:CTL: Setting CSR nonce to random value
[1687931169.329436][1315:1317] CHIP:CTL: Generating NOC
[1687931169.345395][1315:1317] CHIP:FP: Validating NOC chain
[1687931169.392253][1315:1317] CHIP:FP: NOC chain validation successful
[1687931169.392296][1315:1317] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1687931169.392321][1315:1317] CHIP:TS: Last Known Good Time: 2023-06-01T08:25:29
[1687931169.392339][1315:1317] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1687931169.392356][1315:1317] CHIP:TS: Retaining current Last Known Good Time
[1687931170.108098][1315:1317] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1687931170.138714][1315:1317] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-01T08:25:2                                                     9
[1687931170.169755][1315:1317] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001                                                      (Compressed Fabric ID: BC3EE8D1A58AE9C3)
[1687931170.355982][1315:1317] CHIP:CTL: Setting thread operational dataset from parameters
[1687931170.356067][1315:1317] CHIP:CTL: Setting attestation nonce to random value
[1687931170.356148][1315:1317] CHIP:CTL: Setting CSR nonce to random value
[1687931170.356216][1315:1317] CHIP:CTL: Commission called for node ID 0x00000000000004D2
[1687931170.356279][1315:1317] CHIP:DL: Long dispatch time: 1045 ms, for event type 2
[1687931170.365204][1315:1316] CHIP:DL: TRACE: Bus acquired for name C-0523
[1687931170.588803][1315:1316] CHIP:DL: FAIL: NULL apEndpoint->mpAdapter in bluezObjectsSetup
[1687931170.588933][1315:1317] CHIP:DL: PlatformBlueZInit init success
[1687931170.588979][1315:1317] CHIP:DIS: Closing all BLE connections
[1687931170.589050][1315:1317] CHIP:BLE: No adapter available for new connection establishment
[1687931170.589079][1315:1317] CHIP:DL: Long dispatch time: 233 ms, for event type 2
[1687931186.671893][1315:1317] CHIP:DL: Avahi re-register required
[1687931186.681534][1315:1317] CHIP:DL: HandlePlatformSpecificBLEEvent 32785
[1687931186.681628][1315:1317] CHIP:DL: Avahi re-register required
[1687931186.683633][1315:1317] CHIP:DL: HandlePlatformSpecificBLEEvent 32785
[1687931188.193767][1315:1317] CHIP:DL: Avahi client registered
[1687931188.197259][1315:1317] CHIP:DL: HandlePlatformSpecificBLEEvent 32784

2. Log at DK board side during pairing. Actually, it kept advertizing onboarding information.

Fullscreen 7180.新文字文件.txt Download

uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Init CHIP stack
I: 223 [DL]BLE address: CB:35:C4:EE:32:7E
I: 233 [DL]OpenThread started: OK
I: 236 [DL]Setting OpenThread device type to ROUTER
I: 241 [SVR]Server initializing...
I: 244 [TS]Last Known Good Time: 2023-05-10T16:19:04
I: 250 [DMG]AccessControl: initializing
I: 253 [DMG]Examples::AccessControlDelegate::Init
I: 258 [DMG]AccessControl: setting
I: 261 [DMG]DefaultAclStorage: initializing
I: 265 [DMG]DefaultAclStorage: 0 entries loaded
D: 269 [IN]UDP::Init bind&listen port=5540
E: 273 [IN]SO_REUSEPORT failed: 109
D: 276 [IN]UDP::Init bound to port=5540
D: 280 [IN]BLEBase::Init - setting/overriding transport
D: 285 [IN]TransportMgr initialized
I: 293 [ZCL]Using ZAP configuration...
I: 299 [DMG]AccessControlCluster: initializing
I: 303 [ZCL]Initiating Admin Commissioning cluster.
I: 308 [ZCL]On/Off set value: 1 0
I: 311 [ZCL]On/off already set to new value
I: 315 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 322 [IN]SecureSession[0x200034e8]: Allocated Type:1 LSID:36535
I: 328 [DIS]Updating services using commissioning mode 1
I: 333 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 342 [DIS]Failed to advertise commissionable node: 3
E: 347 [DIS]Failed to finalize service update: 1c
I: 352 [DIS]Updating services using commissioning mode 1
I: 357 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 366 [DIS]Failed to advertise commissionable node: 3
E: 371 [DIS]Failed to finalize service update: 1c
I: 376 [DIS]Delaying proxy of operational discovery: missing delegate
I: 382 [IN]CASE Server enabling CASE session setups
D: 387 [IN]SecureSession[0x200035a0]: Allocated Type:2 LSID:36536
I: 393 [SVR]Joining Multicast groups
I: 396 [SVR]Server Listening...
I: 399 [DL]Device Configuration:
I: 402 [DL]  Serial Number: 11223344556677889900
I: 406 [DL]  Vendor Id: 65521 (0xFFF1)
I: 410 [DL]  Product Id: 32773 (0x8005)
I: 413 [DL]  Hardware Version: 1
I: 416 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 422 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 428 [DL]  Manufacturing Date: 2022-02-02
I: 432 [DL]  Device Type: 65535 (0xFFFF)
I: 436 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 440 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 446 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 455 [SVR]Manual pairing code: [34970112332]
I: 460 [DL]CHIP task running
I: 465 [DL]CHIPoBLE advertising started
I: 468 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 473 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 479 [DL]NFC Tag emulation started
I: BLE advertising is already enabled
I: 30468 [DL]CHIPoBLE advertising mode changed to slow
I: 30475 [DL]CHIPoBLE advertising started
I: BLE advertising is already enabled

[Jeffery]

Hi Rusiv

I tried an 3rd-party USB BT4.0 adapter on Raspberry Pi.

hciconfig can found this external adapter.

Then, pairing ble-thread can work successfully no matter the installation through Docker or manual.

So, the problem was from built-in bluetooth of Pi.

At least, we can replace it by external adapter to test Matter.

Thanks.

Jeff  

[runsiv]

Hi Jeff

Glad to hear it works with an external adapter. I will just set this case to closed if that is okey for you? 

Regards

Runar

[Jeffery]

Yes, thanks.