esp-matter icon indicating copy to clipboard operation
esp-matter copied to clipboard

Published 20 hours ago • verified publisher icon espressif

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

Open MaplestoryAlen opened this issue 1 year ago • 6 comments

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 avatar Sep 07 '23 03:09 MaplestoryAlen

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:

MaplestoryAlen avatar Sep 08 '23 08:09 MaplestoryAlen

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

VaishaliAvhale avatar Sep 13 '23 13:09 VaishaliAvhale

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

MaplestoryAlen avatar Sep 14 '23 01:09 MaplestoryAlen

@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.

shubhamdp avatar Sep 15 '23 05:09 shubhamdp

@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

MaplestoryAlen avatar Sep 18 '23 02:09 MaplestoryAlen

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

S-A-M-J avatar Mar 03 '24 22:03 S-A-M-J