Failed to use chip-tool Bluetooth network distribution with error CHIP Error 0x000000AC (CON-751)

MaplestoryAlen commented 10 months ago

The (./chip tool pairing onnetwork) command can be used for network configuration, but Bluetooth cannot be used for network configuration

Describe the bug chip-tool log: Please refer to the following document log.txt

Environment

ESP-Matter Commit Id: 5b4f800
ESP-IDF Commit Id:ESP-IDF v5.1.1
SoC :ESP32-S3
Device Logs (Please attach the log file):
Host Machine OS: Ubuntu20.04
Commissioner app and versions if present:
Commissioner's logs if present:

Any additional details ...

MaplestoryAlen commented 9 months ago

ESP32-H2 chip-tool log CHIP:TOO: Run command failure: src/controller/AutoCommissioner.cpp:218: CHIP Error 0x0000002F: Invalid argument

ESP32-H2 monitor log:

I (1775) app_main: Commissioning window opened I (1775) led_driver_ws2812: led set r:63, g:51, b:40 I (1855) main_task: Returned from app_main()

I (10935) chip[DL]: BLE GAP connection established (con 1) I (10945) chip[DL]: CHIPoBLE advertising stopped I (12265) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (12265) chip[BLE]: local and remote recv window sizes = 5 I (12275) chip[BLE]: selected BTP version 4 I (12285) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. I (12365) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 1 I (12365) chip[DL]: CHIPoBLE subscribe received I (12365) NimBLE: GATT procedure initiated: indicate; I (12385) NimBLE: att_handle=14

I (12465) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (12465) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (12485) chip[EM]: >>> [E:9410r S:0 M:98748697] (U) Msg RX from 0:549AB147F7B35FA9 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I (12495) chip[EM]: <<< [E:9410r S:0 M:107189204] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I (12505) chip[IN]: (U) Sending msg 107189204 to IP address 'BLE' I (12515) NimBLE: GATT procedure initiated: indicate; I (12515) NimBLE: att_handle=14

I (12535) chip[SVR]: Commissioning session establishment step started I (12615) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (12615) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (12635) chip[EM]: >>> [E:9410r S:0 M:98748698] (U) Msg RX from 0:549AB147F7B35FA9 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I (12745) chip[EM]: <<< [E:9410r S:0 M:107189205] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I (12745) chip[IN]: (U) Sending msg 107189205 to IP address 'BLE' I (12755) NimBLE: GATT procedure initiated: indicate; I (12755) NimBLE: att_handle=14

I (12865) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (12865) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (12885) chip[EM]: >>> [E:9410r S:0 M:98748699] (U) Msg RX from 0:549AB147F7B35FA9 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I (12895) chip[EM]: <<< [E:9410r S:0 M:107189206] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I (12905) chip[IN]: (U) Sending msg 107189206 to IP address 'BLE' I (12915) NimBLE: GATT procedure initiated: indicate; I (12915) NimBLE: att_handle=14

I (12925) chip[SC]: SecureSession[0x40815278, LSID:63917]: State change 'kEstablishing' --> 'kActive' I (12935) chip[SVR]: Commissioning completed session establishment step I (12935) chip[DIS]: Updating services using commissioning mode 0 E (12945) chip[DIS]: Failed to remove advertised services: 3 I (12945) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 E (12965) chip[DIS]: Failed to advertise extended commissionable node: 3 E (12975) chip[DIS]: Failed to finalize service update: 3 I (12975) chip[SVR]: Device completed Rendezvous process I (12975) app_main: Commissioning session started I (12995) app_main: Commissioning window closed I (13015) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (13025) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (13035) chip[EM]: >>> [E:9411r S:63917 M:31816379] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I (13045) chip[DMG]: Registered a ReadHandler that will schedule a report between system Timestamp: 13046 and system Timestamp 13046. I (13055) esp_matter_attribute: ** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 ** I (13075) chip[EM]: <<< [E:9411r S:63917 M:214414024] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I (13075) chip[IN]: (S) Sending msg 214414024 on secure session with LSID: 63917 I (13095) NimBLE: GATT procedure initiated: indicate; I (13095) NimBLE: att_handle=14

I (13165) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (13165) NimBLE: GATT procedure initiated: indicate; I (13185) NimBLE: att_handle=14

I (13265) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (13265) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (13285) chip[EM]: >>> [E:9412r S:63917 M:31816380] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (13285) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030 I (13305) chip[FS]: GeneralCommissioning: Received ArmFailSafe (60s) I (13315) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 4 ** I (13325) chip[EM]: <<< [E:9412r S:63917 M:214414025] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (13335) chip[IN]: (S) Sending msg 214414025 on secure session with LSID: 63917 I (13345) NimBLE: GATT procedure initiated: indicate; I (13345) NimBLE: att_handle=14

I (13415) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (13415) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (13435) chip[EM]: >>> [E:9413r S:63917 M:31816381] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (13435) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x00000030 I (13455) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0) I (13455) chip[DL]: NVS set: chip-config/country-code = "XX" I (13465) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 5 ** I (13485) chip[EM]: <<< [E:9413r S:63917 M:214414026] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (13485) chip[IN]: (S) Sending msg 214414026 on secure session with LSID: 63917 I (13495) NimBLE: GATT procedure initiated: indicate; I (13505) NimBLE: att_handle=14

I (13565) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (13565) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (13585) chip[EM]: >>> [E:9414r S:63917 M:31816382] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (13585) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E I (13605) chip[ZCL]: OpCreds: Certificate Chain request received for PAI I (13625) chip[EM]: <<< [E:9414r S:63917 M:214414027] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (13625) chip[IN]: (S) Sending msg 214414027 on secure session with LSID: 63917 I (13635) NimBLE: GATT procedure initiated: indicate; I (13635) NimBLE: att_handle=14

I (13715) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (13715) NimBLE: GATT procedure initiated: indicate; I (13735) NimBLE: att_handle=14

I (13815) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (13815) NimBLE: GATT procedure initiated: indicate; I (13835) NimBLE: att_handle=14

I (13915) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (13915) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (13935) chip[EM]: >>> [E:9415r S:63917 M:31816383] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (13935) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E I (13955) chip[ZCL]: OpCreds: Certificate Chain request received for DAC I (13975) chip[EM]: <<< [E:9415r S:63917 M:214414028] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (13975) chip[IN]: (S) Sending msg 214414028 on secure session with LSID: 63917 I (13985) NimBLE: GATT procedure initiated: indicate; I (13985) NimBLE: att_handle=14

I (14065) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (14065) NimBLE: GATT procedure initiated: indicate; I (14085) NimBLE: att_handle=14

I (14165) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (14165) NimBLE: GATT procedure initiated: indicate; I (14185) NimBLE: att_handle=14

I (14265) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (14265) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (14285) chip[EM]: >>> [E:9416r S:63917 M:31816384] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (14285) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x0000003E I (14305) chip[ZCL]: OpCreds: Received an AttestationRequest command I (14345) chip[ZCL]: OpCreds: AttestationRequest successful. I (14355) chip[EM]: <<< [E:9416r S:63917 M:214414029] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (14355) chip[IN]: (S) Sending msg 214414029 on secure session with LSID: 63917 I (14365) NimBLE: GATT procedure initiated: indicate; I (14375) NimBLE: att_handle=14

I (14465) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (14465) NimBLE: GATT procedure initiated: indicate; I (14485) NimBLE: att_handle=14

I (14565) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (14565) NimBLE: GATT procedure initiated: indicate; I (14585) NimBLE: att_handle=14

I (14665) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (14665) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (14685) chip[EM]: >>> [E:9417r S:63917 M:31816385] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (14685) esp_matter_command: Received command 0x00000004 for endpoint 0x0000's cluster 0x0000003E I (14705) chip[ZCL]: OpCreds: Received a CSRRequest command I (14755) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded I (14785) chip[ZCL]: OpCreds: CSRRequest successful. I (14795) chip[EM]: <<< [E:9417r S:63917 M:214414030] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (14795) chip[IN]: (S) Sending msg 214414030 on secure session with LSID: 63917 I (14805) NimBLE: GATT procedure initiated: indicate; I (14805) NimBLE: att_handle=14

I (14915) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (14915) NimBLE: GATT procedure initiated: indicate; I (14935) NimBLE: att_handle=14

I (15015) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (15025) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (15115) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (15125) chip[EM]: >>> [E:9418r S:63917 M:31816386] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (15135) esp_matter_command: Received command 0x0000000B for endpoint 0x0000's cluster 0x0000003E I (15145) chip[ZCL]: OpCreds: Received an AddTrustedRootCertificate command I (15185) chip[ZCL]: OpCreds: AddTrustedRootCertificate successful. I (15185) chip[EM]: <<< [E:9418r S:63917 M:214414031] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (15205) chip[IN]: (S) Sending msg 214414031 on secure session with LSID: 63917 I (15205) NimBLE: GATT procedure initiated: indicate; I (15215) NimBLE: att_handle=14

I (15315) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (15325) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (15415) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (15515) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (15525) chip[EM]: >>> [E:9419r S:63917 M:31816387] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (15525) esp_matter_command: Received command 0x00000006 for endpoint 0x0000's cluster 0x0000003E I (15545) chip[ZCL]: OpCreds: Received an AddNOC command I (15545) chip[FP]: Validating NOC chain I (15615) chip[FP]: NOC chain validation successful I (15615) chip[FP]: Added new fabric at index: 0x1 I (15615) chip[FP]: Assigned compressed fabric ID: 0x2660567B01C70955, node ID: 0x0000000000000070 I (15635) chip[TS]: Last Known Good Time: 2023-09-05T17:17:15 I (15635) chip[TS]: New proposed Last Known Good Time: 2021-01-01T00:00:00 I (15645) chip[TS]: Retaining current Last Known Good Time I (15655) chip[ZCL]: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 I (15665) chip[DIS]: Advertise operational node 2660567B01C70955-0000000000000070 I (15675) chip[ZCL]: OpCreds: successfully created fabric index 0x1 via AddNOC I (15675) chip[EM]: <<< [E:9419r S:63917 M:214414032] (S) Msg TX to 1:FFFFFFFB00000000 [0955] --- Type 0001:09 (IM:InvokeCommandResponse) I (15695) chip[IN]: (S) Sending msg 214414032 on secure session with LSID: 63917 I (15705) NimBLE: GATT procedure initiated: indicate; I (15705) NimBLE: att_handle=14

I (15705) app_main: Fabric is updated I (15765) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (15765) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (15785) chip[EM]: >>> [E:9420r S:63917 M:31816388] (S) Msg RX from 1:FFFFFFFB00000000 [0955] --- Type 0001:08 (IM:InvokeCommandRequest) I (15785) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030 I (15805) chip[FS]: GeneralCommissioning: Received ArmFailSafe (0s) I (15815) chip[FS]: Fail-safe timer expired I (15815) chip[EM]: <<< [E:9420r S:63917 M:214414033] (S) Msg TX to 1:FFFFFFFB00000000 [0955] --- Type 0001:09 (IM:InvokeCommandResponse) I (15825) chip[IN]: (S) Sending msg 214414033 on secure session with LSID: 63917 I (15835) NimBLE: GATT procedure initiated: indicate; I (15835) NimBLE: att_handle=14

E (15845) chip[SVR]: Failsafe timer expired I (15855) chip[SC]: SecureSession[0x40815278, LSID:63917]: State change 'kActive' --> 'kPendingEviction' E (15865) chip[SVR]: Commissioning failed (attempt 1): 32 I (15865) chip[BLE]: Releasing end point's BLE connection back to application. I (15885) chip[DIS]: Updating services using commissioning mode 1 E (15885) chip[DIS]: Failed to remove advertised services: 3 I (15885) chip[DIS]: Advertise operational node 2660567B01C70955-0000000000000070 E (15895) chip[DIS]: Failed to advertise operational node: 3 I (15905) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 E (15915) chip[DIS]: Failed to advertise commissionable node: 3 E (15925) chip[DIS]: Failed to finalize service update: 3 E (15925) chip[ZCL]: OpCreds: Got FailSafeTimerExpired E (15935) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! E (15935) chip[FP]: Reverting pending fabric data for fabric 0x1 E (15955) chip[FP]: Warning: metadata not found during delete of fabric 0x1 I (15915) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 I (15965) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0 I (15975) chip[DL]: CHIPoBLE unsubscribe received I (15975) chip[FP]: Fabric (0x1) deleted. I (15985) chip[ZCL]: OpCreds: Fabric index 0x1 was removed I (15995) chip[DIS]: Updating services using commissioning mode 1 E (16005) chip[DIS]: Failed to remove advertised services: 3 I (16005) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 E (16015) chip[DIS]: Failed to advertise commissionable node: 3 E (16015) chip[DIS]: Failed to finalize service update: 3 I (16075) chip[TS]: Pending Last Known Good Time: 2023-09-05T17:17:15 I (16075) chip[TS]: Previous Last Known Good Time: 2023-09-05T17:17:15 I (16085) chip[TS]: Reverted Last Known Good Time to previous value E (16095) chip[FP]: Warning: metadata not found during delete of fabric 0x1 E (16105) chip[ZCL]: OpCreds: failed to delete fabric at index 1: d8 I (16105) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 ** I (16115) app_main: Commissioning failed, fail safe timer expired I (16125) chip[FS]: Fail-safe cleanly disarmed I (16135) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable) I (16145) NimBLE: GAP procedure initiated: advertise; I (16145) NimBLE: disc_mode=2 I (16145) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (16155) NimBLE:

I (16165) chip[DL]: CHIPoBLE advertising started I (16165) app_main: Commissioning window opened I (16175) app_main: Fabric will be removed E (16175) chip[BLE]: no endpoint for BLE sent data ack E (16185) chip[BLE]: no endpoint for unsub recvd I (16185) app_main: Fabric removed successfully I (16185) app_main: Fabric will be removed I (18665) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213) I (18665) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable) I (18675) chip[DL]: Device already advertising, stop active advertisement and restart I (18685) NimBLE: GAP procedure initiated: stop advertising.

I (18695) NimBLE: GAP procedure initiated: advertise; I (18695) NimBLE: disc_mode=2 I (18695) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (18715) NimBLE:

VaishaliAvhale commented 9 months ago

Please provide the complete device and chip-tool logs in a file format.

MaplestoryAlen commented 9 months ago

Please provide the complete device and chip-tool logs in a file format. Please review log.txt

shubhamdp commented 9 months ago

@MaplestoryAlen log.txt shows that device failed to connect to wifi network.

In first comment you said SoC :ESP32-S3 and in subsequent comment you said you are commissioning H2. Can you confirm which SoC you are using.

H2 is a 802.15.4 device and ble-wifi won't work on that. You would need to use ble-thread command and you must need a border router for commissioning the h2.

MaplestoryAlen commented 9 months ago

@MaplestoryAlen log.txt shows that device failed to connect to wifi network.

In first comment you said SoC :ESP32-S3 and in subsequent comment you said you are commissioning H2. Can you confirm which SoC you are using.

H2 is a 802.15.4 device and ble-wifi won't work on that. You would need to use ble-thread command and you must need a border router for commissioning the h2.

I have also set up the border router and it can work normally. However, H2 and S3 cannot access the network using Bluetooth, and the hub uses Apple audio

S-A-M-J commented 4 months ago

I have the same issue on an esp32-c3. ESP-IDF: 5.2 When using an amazon alexa device to discover the device, the device is found but Alexa tells me to enter wifi creds in a loop while never fully connecting. This is despite the chip being provisioned already. The code i'm using is the light example from esp matter. Logs below If i disable chip over ble the device is found by alexa but alexa is unable to connect. log1.txt

espressif / esp-matter

Failed to use chip-tool Bluetooth network distribution with error CHIP Error 0x000000AC (CON-751) #620