Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

What exactly is going wrong with the commissioning (TZ-1006) #81

Closed
pavel808 opened this issue Jul 16, 2024 · 12 comments
Closed

What exactly is going wrong with the commissioning (TZ-1006) #81

pavel808 opened this issue Jul 16, 2024 · 12 comments

Comments

@pavel808
Copy link

I have an ESP32-C6 board and I have flashed the simple Matter light example onto it.

I have this ESP Thread Border Router too : https://docs.espressif.com/projects/esp-thread-br/en/latest/hardware_platforms.html

I have built and flashed the ESP32-S3 chip on the TBR as described here : https://docs.espressif.com/projects/esp-thread-br/en/latest/hardware_platforms.html

I then connect the TBR to my local wi-fi network, activate the dataset and Thread network as doscumented, and all looks good from the TBR console from the ESP32-S3 chip.

Now I am trying to use chip-tool to commission the ESP32-C6 Matter light example over Thread via the TBR which is set up. :

chip-tool pairing code-thread 0x7293 hex:0e080000000000010000000300000f35060004001fffe002081b298d83a096e8ec0708fd7619a99f322224051075ccd01fae3d13d83aeab1d1f6b6dc60030f4f70656e5468726561642d3261653301022ae30410b9a844ce2468bddd8363622d256e20df0c0402a0f7f8 34970112332

The commissioning fails with the following error from chip-tool :

Run command failure: src/controller/AutoCommissioner.cpp:313: CHIP Error 0x0000002F: Invalid argument

Below are logs from the ESP32-C6 Matter light example. I don't understand what is the issue. Am I missing a step? I'd appreciate any help with this. Thanks :

Run command failure: src/controller/AutoCommissioner.cpp:313: CHIP Error 0x0000002F: Invalid argument

�[0;32mI (59872) chip[DL]: BLE GAP connection established (con 1)�[0m
�[0;32mI (59882) chip[DL]: CHIPoBLE advertising stopped�[0m
�[0;32mI (61332) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (61332) chip[BLE]: local and remote recv window sizes = 5�[0m
�[0;32mI (61352) chip[BLE]: selected BTP version 4�[0m
�[0;32mI (61352) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.�[0m
�[0;32mI (61422) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 1�[0m
�[0;32mI (61422) chip[DL]: CHIPoBLE subscribe received�[0m
�[0;32mI (61422) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (61442) NimBLE: att_handle=18
�[0m
�[0;32mI (61512) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (61522) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (61532) chip[EM]: >>> [E:51852r S:0 M:110081530] (U) Msg RX from 0:ECBA39A3591AA9E1 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)�[0m
�[0;32mI (61542) chip[EM]: <<< [E:51852r S:0 M:126723913] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)�[0m
�[0;32mI (61552) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (61562) NimBLE: att_handle=18
�[0m
�[0;32mI (61572) chip[SVR]: Commissioning session establishment step started�[0m
�[0;32mI (61692) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (61702) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (61712) chip[EM]: >>> [E:51852r S:0 M:110081531] (U) Msg RX from 0:ECBA39A3591AA9E1 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)�[0m
�[0;32mI (61782) chip[EM]: <<< [E:51852r S:0 M:126723914] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2)�[0m
�[0;32mI (61792) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (61792) NimBLE: att_handle=18
�[0m
�[0;32mI (61872) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (61882) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (61892) chip[EM]: >>> [E:51852r S:0 M:110081532] (U) Msg RX from 0:ECBA39A3591AA9E1 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)�[0m
�[0;32mI (61902) chip[EM]: <<< [E:51852r S:0 M:126723915] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport)�[0m
�[0;32mI (61912) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (61922) NimBLE: att_handle=18
�[0m
�[0;32mI (61932) chip[SC]: SecureSession[0x40823308, LSID:4587]: State change 'kEstablishing' --> 'kActive'�[0m
�[0;32mI (61942) chip[SVR]: Commissioning completed session establishment step�[0m
�[0;32mI (61942) chip[DIS]: Updating services using commissioning mode 0�[0m
�[0;32mI (61952) chip[DIS]: CHIP minimal mDNS started advertising.�[0m
�[0;32mI (61952) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 cp=0�[0m
�[0;32mI (61962) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: E3E68C5E6BE31851.�[0m
�[0;32mI (61972) chip[DIS]: mDNS service published: _matterc._udp�[0m
�[0;32mI (61982) chip[SVR]: Device completed Rendezvous process�[0m
�[0;32mI (61992) app_main: Commissioning session started�[0m
�[0;32mI (62002) app_main: Commissioning window closed�[0m
�[0;32mI (62012) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (62012) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (62022) chip[EM]: >>> [E:51853r S:4587 M:177445197] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)�[0m
�[0;32mI (62042) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)�[0m
�[0;32mI (62042) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 **********�[0m
�[0;32mI (62062) chip[EM]: <<< [E:51853r S:4587 M:83904129] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)�[0m
�[0;32mI (62072) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (62072) NimBLE: att_handle=18
�[0m
�[0;32mI (62142) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (62152) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (62162) NimBLE: att_handle=18
�[0m
�[0;32mI (62232) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (62242) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (62252) chip[EM]: >>> [E:51854r S:4587 M:177445198] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)�[0m
�[0;32mI (62262) chip[EM]: <<< [E:51854r S:4587 M:83904130] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)�[0m
�[0;32mI (62282) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (62282) NimBLE: att_handle=18
�[0m
�[0;32mI (62322) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (62332) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (62342) chip[EM]: >>> [E:51855r S:4587 M:177445199] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (62352) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030�[0m
�[0;32mI (62362) chip[FS]: GeneralCommissioning: Received ArmFailSafe (60s)�[0m
�[0;32mI (62362) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 4 **********�[0m
�[0;32mI (62372) app_main: app_attribute_update_cb for end point : 0, cluster id : 48,  attribute id : 0 �[0m
�[0;32mI (62392) app_driver: app_driver_attribute_update for end point : 0, cluster id : 48,  attribute id : 0�[0m
�[0;31mE (62402) esp_matter_core: Cluster cannot be NULL�[0m
�[0;32mI (62402) app_main: app_attribute_update_cb for end point : 0, cluster id : 48,  attribute id : 0 �[0m
�[0;32mI (62412) chip[EM]: <<< [E:51855r S:4587 M:83904131] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (62422) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (62432) NimBLE: att_handle=18
�[0m
�[0;32mI (62502) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (62552) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (62552) chip[EM]: >>> [E:51856r S:4587 M:177445200] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (62562) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x00000030�[0m
�[0;32mI (62582) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)�[0m
�[0;32mI (62592) chip[DL]: NVS set: chip-config/country-code = "XX"�[0m
�[0;32mI (62592) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 5 **********�[0m
�[0;32mI (62602) app_main: app_attribute_update_cb for end point : 0, cluster id : 48,  attribute id : 0 �[0m
�[0;32mI (62612) app_driver: app_driver_attribute_update for end point : 0, cluster id : 48,  attribute id : 0�[0m
�[0;31mE (62622) esp_matter_core: Cluster cannot be NULL�[0m
�[0;32mI (62622) app_main: app_attribute_update_cb for end point : 0, cluster id : 48,  attribute id : 0 �[0m
�[0;32mI (62632) chip[EM]: <<< [E:51856r S:4587 M:83904132] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (62652) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (62662) NimBLE: att_handle=18
�[0m
�[0;32mI (62732) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (62732) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (62742) chip[EM]: >>> [E:51857r S:4587 M:177445201] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (62762) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E�[0m
�[0;32mI (62772) chip[ZCL]: OpCreds: Certificate Chain request received for PAI�[0m
�[0;32mI (62772) chip[EM]: <<< [E:51857r S:4587 M:83904133] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (62782) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (62792) NimBLE: att_handle=18
�[0m
�[0;32mI (62862) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (62862) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (62882) NimBLE: att_handle=18
�[0m
�[0;32mI (62952) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (62952) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (62972) NimBLE: att_handle=18
�[0m
�[0;32mI (63042) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63052) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (63062) chip[EM]: >>> [E:51858r S:4587 M:177445202] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (63072) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E�[0m
�[0;32mI (63082) chip[ZCL]: OpCreds: Certificate Chain request received for DAC�[0m
�[0;32mI (63092) chip[EM]: <<< [E:51858r S:4587 M:83904134] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (63102) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (63112) NimBLE: att_handle=18
�[0m
�[0;32mI (63182) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63182) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (63192) NimBLE: att_handle=18
�[0m
�[0;32mI (63272) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63272) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (63282) NimBLE: att_handle=18
�[0m
�[0;32mI (63362) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63362) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (63372) chip[EM]: >>> [E:51859r S:4587 M:177445203] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (63392) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x0000003E�[0m
�[0;32mI (63402) chip[ZCL]: OpCreds: Received an AttestationRequest command�[0m
�[0;32mI (63422) chip[ZCL]: OpCreds: AttestationRequest successful.�[0m
�[0;32mI (63422) chip[EM]: <<< [E:51859r S:4587 M:83904135] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (63432) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (63432) NimBLE: att_handle=18
�[0m
�[0;32mI (63492) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63492) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (63512) NimBLE: att_handle=18
�[0m
�[0;32mI (63582) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63582) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (63602) NimBLE: att_handle=18
�[0m
�[0;32mI (63672) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63682) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (63692) chip[EM]: >>> [E:51860r S:4587 M:177445204] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (63702) esp_matter_command: Received command 0x00000004 for endpoint 0x0000's cluster 0x0000003E�[0m
�[0;32mI (63712) chip[ZCL]: OpCreds: Received a CSRRequest command�[0m
�[0;32mI (63742) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded�[0m
�[0;32mI (63762) chip[ZCL]: OpCreds: CSRRequest successful.�[0m
�[0;32mI (63762) chip[EM]: <<< [E:51860r S:4587 M:83904136] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (63772) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (63772) NimBLE: att_handle=18
�[0m
�[0;32mI (63852) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63852) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (63872) NimBLE: att_handle=18
�[0m
�[0;32mI (63952) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (63952) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (64032) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (64042) chip[EM]: >>> [E:51861r S:4587 M:177445205] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (64052) esp_matter_command: Received command 0x0000000B for endpoint 0x0000's cluster 0x0000003E�[0m
�[0;32mI (64062) chip[ZCL]: OpCreds: Received an AddTrustedRootCertificate command�[0m
�[0;32mI (64092) chip[ZCL]: OpCreds: AddTrustedRootCertificate successful.�[0m
�[0;32mI (64092) chip[EM]: <<< [E:51861r S:4587 M:83904137] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (64112) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (64112) NimBLE: att_handle=18
�[0m
�[0;32mI (64172) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (64172) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (64262) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (64352) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (64352) chip[EM]: >>> [E:51862r S:4587 M:177445206] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (64372) esp_matter_command: Received command 0x00000006 for endpoint 0x0000's cluster 0x0000003E�[0m
�[0;32mI (64382) chip[ZCL]: OpCreds: Received an AddNOC command�[0m
�[0;32mI (64382) chip[FP]: Validating NOC chain�[0m
�[0;32mI (64442) chip[FP]: NOC chain validation successful�[0m
�[0;32mI (64442) chip[FP]: Added new fabric at index: 0x1�[0m
�[0;32mI (64442) chip[FP]: Assigned compressed fabric ID: 0xE8BD1739F4EEBED6, node ID: 0x0000000000007293�[0m
�[0;32mI (64452) chip[TS]: Last Known Good Time: 2023-10-14T01:16:48�[0m
�[0;32mI (64462) chip[TS]: New proposed Last Known Good Time: 2021-01-01T00:00:00�[0m
�[0;32mI (64462) chip[TS]: Retaining current Last Known Good Time�[0m
�[0;32mI (64482) chip[ZCL]: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669�[0m
�[0;32mI (64482) chip[DIS]: Advertise operational node E8BD1739F4EEBED6-0000000000007293�[0m
�[0;32mI (64492) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: E8BD1739F4EEBED6-0000000000007293.�[0m
�[0;32mI (64512) chip[DIS]: mDNS service published: _matter._tcp�[0m
�[0;32mI (64522) chip[ZCL]: OpCreds: successfully created fabric index 0x1 via AddNOC�[0m
�[0;32mI (64522) chip[EM]: <<< [E:51862r S:4587 M:83904138] (S) Msg TX to 1:FFFFFFFB00000000 [BED6] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (64532) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (64542) NimBLE: att_handle=18
�[0m
�[0;32mI (64542) app_main: Fabric is updated�[0m
�[0;32mI (64622) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (64622) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16�[0m
�[0;32mI (64632) chip[EM]: >>> [E:51863r S:4587 M:177445207] (S) Msg RX from 1:FFFFFFFB00000000 [BED6] --- Type 0001:08 (IM:InvokeCommandRequest)�[0m
�[0;32mI (64652) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030�[0m
�[0;32mI (64662) chip[FS]: GeneralCommissioning: Received ArmFailSafe (0s)�[0m
�[0;32mI (64662) chip[FS]: Fail-safe timer expired�[0m
�[0;32mI (64672) chip[EM]: <<< [E:51863r S:4587 M:83904139] (S) Msg TX to 1:FFFFFFFB00000000 [BED6] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)�[0m
�[0;32mI (64682) NimBLE: GATT procedure initiated: indicate; �[0m
�[0;32mI (64682) NimBLE: att_handle=18
�[0m
�[0;31mE (64692) chip[SVR]: Failsafe timer expired�[0m
�[0;32mI (64702) chip[SC]: SecureSession[0x40823308, LSID:4587]: State change 'kActive' --> 'kPendingEviction'�[0m
�[0;31mE (64712) chip[SVR]: Commissioning failed (attempt 1): 32�[0m
�[0;32mI (64712) chip[BLE]: Releasing end point's BLE connection back to application.�[0m
�[0;32mI (64722) chip[DIS]: Updating services using commissioning mode 1�[0m
�[0;32mI (64722) chip[DIS]: CHIP minimal mDNS started advertising.�[0m
�[0;32mI (64732) chip[DIS]: Advertise operational node E8BD1739F4EEBED6-0000000000007293�[0m
�[0;32mI (64742) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: E8BD1739F4EEBED6-0000000000007293.�[0m
�[0;32mI (64762) chip[DIS]: mDNS service published: _matter._tcp�[0m
�[0;32mI (64762) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 cp=0�[0m
�[0;32mI (64772) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: E3E68C5E6BE31851.�[0m
�[0;32mI (64782) chip[DIS]: mDNS service published: _matterc._udp�[0m
�[0;31mE (64782) chip[ZCL]: OpCreds: Got FailSafeTimerExpired�[0m
�[0;31mE (64792) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!�[0m
�[0;31mE (64802) chip[FP]: Reverting pending fabric data for fabric 0x1�[0m
�[0;32mI (64752) chip[DL]: �[0;31mE (64812) chip[FP]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 �[0m
�[0;32mI (64822) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0�[0m
�[0;32mI (64832) chip[DL]: CHIPoBLE unsubscribe received�[0m
Warning: metadata not found during delete of fabric 0x1�[0m
�[0;32mI (64842) chip[FP]: Fabric (0x1) deleted.�[0m
�[0;32mI (64842) chip[ZCL]: OpCreds: Fabric index 0x1 was removed�[0m
�[0;32mI (64852) chip[DIS]: Updating services using commissioning mode 1�[0m
�[0;32mI (64852) chip[DIS]: CHIP minimal mDNS started advertising.�[0m
�[0;32mI (64872) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 cp=0�[0m
�[0;32mI (64882) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: E3E68C5E6BE31851.�[0m
�[0;32mI (64892) chip[DIS]: mDNS service published: _matterc._udp�[0m
�[0;32mI (64912) chip[TS]: Pending Last Known Good Time: 2023-10-14T01:16:48�[0m
�[0;32mI (64912) chip[TS]: Previous Last Known Good Time: 2023-10-14T01:16:48�[0m
�[0;32mI (64922) chip[TS]: Reverted Last Known Good Time to previous value�[0m
�[0;31mE (64922) chip[FP]: Warning: metadata not found during delete of fabric 0x1�[0m
�[0;31mE (64932) chip[ZCL]: OpCreds: failed to delete fabric at index 1: d8�[0m
�[0;32mI (64932) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 **********�[0m
�[0;32mI (64942) app_main: app_attribute_update_cb for end point : 0, cluster id : 48,  attribute id : 0 �[0m
�[0;32mI (64952) app_driver: app_driver_attribute_update for end point : 0, cluster id : 48,  attribute id : 0�[0m
�[0;31mE (64972) esp_matter_core: Cluster cannot be NULL�[0m
�[0;32mI (64982) app_main: app_attribute_update_cb for end point : 0, cluster id : 48,  attribute id : 0 �[0m
�[0;32mI (64982) app_main: Commissioning failed, fail safe timer expired�[0m
�[0;32mI (64992) chip[FS]: Fail-safe cleanly disarmed�[0m
�[0;32mI (64992) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)�[0m
�[0;32mI (65002) NimBLE: GAP procedure initiated: advertise; �[0m
�[0;32mI (65012) NimBLE: disc_mode=2�[0m
�[0;32mI (65012) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40�[0m
�[0;32mI (65022) NimBLE: 
�[0m
�[0;32mI (65032) chip[DL]: CHIPoBLE advertising started�[0m
�[0;32mI (65032) app_main: Commissioning window opened�[0m
�[0;32mI (65042) app_main: Fabric will be removed�[0m
�[0;31mE (65042) chip[BLE]: no endpoint for BLE sent data ack�[0m
�[0;31mE (65052) chip[BLE]: no endpoint for unsub recvd�[0m
�[0;32mI (65052) app_main: Fabric removed successfully�[0m
�[0;32mI (65062) app_main: Fabric will be removed�[0m
�[0;32mI (66872) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213)�[0m
�[0;32mI (66872) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)�[0m
�[0;32mI (66882) chip[DL]: Device already advertising, stop active advertisement and restart�[0m
�[0;32mI (66882) NimBLE: GAP procedure initiated: stop advertising.
�[0m
�[0;32mI (66892) NimBLE: GAP procedure initiated: advertise; �[0m
�[0;32mI (66892) NimBLE: disc_mode=2�[0m
�[0;32mI (66902) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40�[0m
�[0;32mI (66922) NimBLE: 
�[0m
�[0;32mI (66922) esp_matter_core: BLE Disconnected�[0m
�[0;32mI (94722) chip[DL]: bleAdv Timeout : Start slow advertisement�[0m
�[0;32mI (94722) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)�[0m
�[0;32mI (94732) chip[DL]: Device already advertising, stop active advertisement and restart�[0m
�[0;32mI (94732) NimBLE: GAP procedure initiated: stop advertising.
�[0m
�[0;32mI (94742) NimBLE: GAP procedure initiated: advertise; �[0m
�[0;32mI (94742) NimBLE: disc_mode=2�[0m
�[0;32mI (94752) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800�[0m
�[0;32mI (94762) NimBLE: 
�[0m

@github-actions github-actions bot changed the title What exactly is going wrong with the commissioning What exactly is going wrong with the commissioning (TZ-1006) Jul 16, 2024
@chshu
Copy link
Collaborator

chshu commented Jul 17, 2024

@pavel808 In esp-matter light example, the default configure for C6 is Wi-Fi, have you changed to this sdkconfig sdkconfig.defaults.c6_thread to build C6 firmware?

@pavel808
Copy link
Author

@chshu Ah, now we're getting somewhere. I haven't actually. I tried to view and change settings using idf.py menuconfig but didn't see a suitable option there.

In this case, how do I make the sdkconfig.defaults.c6_thread active? Should I rename this file to sdkconfig.defaults ?

@chshu
Copy link
Collaborator

chshu commented Jul 17, 2024

You can simply replace the sdkconfig.defaults with sdkconfig.defaults.c6_thread, and rebuild the example.

@pavel808
Copy link
Author

Hi @chshu . Thanks. However, no matter what I try to do to enable Thread instead of Wi-Fi I get build errors as below due to partitioning size issues. I tried changing different options in the sdkconfig.defaults without success. I tried reverting the sdkconfig.defaults to the original (this builds), then changing different options via idf.py menuconfig such as enabling Thread options, changing Flash size, disabling OTA etc. Nothing seems to solve this after about 30+ builds:)

Successfully created esp32c6 image.
Generated /home/user/MatterEdgeDevice/esp-matter/examples/edge-controller/build/light.bin
[2063/2063] cd /home/user/MatterEdgeDevice/esp-matter/examples/edge-controller/build/es...ble.bin /home/user/MatterEdgeDevice/esp-matter/examples/edge-controller/build/light.bin
FAILED: esp-idf/esptool_py/CMakeFiles/app_check_size /home/user/MatterEdgeDevice/esp-matter/examples/edge-controller/build/esp-idf/esptool_py/CMakeFiles/app_check_size 
cd /home/user/MatterEdgeDevice/esp-matter/examples/edge-controller/build/esp-idf/esptool_py && /home/user/.espressif/python_env/idf5.2_py3.10_env/bin/python /home/user/esp-idf/components/partition_table/check_sizes.py --offset 0xc000 partition --type app /home/user/MatterEdgeDevice/esp-matter/examples/edge-controller/build/partition_table/partition-table.bin /home/user/MatterEdgeDevice/esp-matter/examples/edge-controller/build/light.bin
Error: All app partitions are too small for binary light.bin size 0x1f60a0:
  - Part 'ota_0' 0/16 @ 0x20000 size 0x1e0000 (overflow 0x160a0)
  - Part 'ota_1' 0/17 @ 0x200000 size 0x1e0000 (overflow 0x160a0)
ninja: build stopped: subcommand failed.

@chshu
Copy link
Collaborator

chshu commented Jul 17, 2024

Seems you were testing your own application edge-controller, and its firmware size is too big to fit in the default partition table, so you need to modify the partition table and increase the ota_0 size.

Could you please test the default light example first, just to ensure your test environment is all good.

@pavel808
Copy link
Author

@chshu Unfortunately it's the same story for the original light application. What i'm doing is just enabling Open Thread via idf.py menuconfig, and nothing more.

idf.py set-target esp32-c6
idf.py menuconfig (Component config->OpenThread. Enable it with the [*])
idf.py build

Successfully created esp32c6 image.
Generated /home/user/esp-matter/examples/light/build/light.bin
[1959/1959] cd /home/user/esp-matter/examples/light/build/esp-idf/esptool_py && /home/u...artition_table/partition-table.bin /home/user/esp-matter/examples/light/build/light.bin
FAILED: esp-idf/esptool_py/CMakeFiles/app_check_size /home/user/esp-matter/examples/light/build/esp-idf/esptool_py/CMakeFiles/app_check_size 
cd /home/user/esp-matter/examples/light/build/esp-idf/esptool_py && /home/user/.espressif/python_env/idf5.2_py3.10_env/bin/python /home/user/esp-idf/components/partition_table/check_sizes.py --offset 0xc000 partition --type app /home/user/esp-matter/examples/light/build/partition_table/partition-table.bin /home/user/esp-matter/examples/light/build/light.bin
Error: All app partitions are too small for binary light.bin size 0x1f3a50:
  - Part 'ota_0' 0/16 @ 0x20000 size 0x1e0000 (overflow 0x13a50)
  - Part 'ota_1' 0/17 @ 0x200000 size 0x1e0000 (overflow 0x13a50)
ninja: build stopped: subcommand failed.
ninja failed with exit code 1, output of the command is in the /home/user/esp-matter/examples/light/build/log/idf_py_stderr_output_300207 and /home/user/esp-matter/examples/light/build/log/idf_py_stdout_output_300207

@pavel808
Copy link
Author

@chshu I tried increasing the Flash size to 8MB via menuconfig. However it fails on bootup stating that the detected Flash size is only 4MB. I'm not sure why, because The ESP32-C6-DevKitC-1 should have 8MB of Flash.

Anyways I modified the partitions.csv file as follows just have one app partition :

# Name,   Type, SubType, Offset,  Size, Flags
# Note: Firmware partition offset needs to be 64K aligned, initial 36K (9 sectors) are reserved for bootloader and partition table
esp_secure_cert,  0x3F, ,0xd000,    0x2000, encrypted
nvs,      data, nvs,     0x10000,   0xC000,
nvs_keys, data, nvs_keys,,          0x1000, encrypted
otadata,  data, ota,     ,          0x2000
phy_init, data, phy,     ,          0x1000,
ota_0,    app,  ota_0,   0x20000,   0x3C0000,
fctry,    data, nvs,     0x3E0000,  0x6000

The app now builds and runs. On attempting to commission the device via chip-tool and the TBR, it goes further in the commissioning process but eventually fails. I've attached the logs here from chip-tool. Any idea what could be potentially be still missing? Again, thanks for your help.

commmission-thread-fail.txt

@chshu
Copy link
Collaborator

chshu commented Jul 18, 2024

@pavel808 please follow this instruction to switch from Matter over Wi-Fi to Thread: #81 (comment)

idf.py menuconfig (Component config->OpenThread. Enable it with the [*]) this way will compile both Wi-Fi and Thread to the firmware, so increases the binary size.

@pavel808
Copy link
Author

@pavel808 please follow this instruction to switch from Matter over Wi-Fi to Thread: #81 (comment)

idf.py menuconfig (Component config->OpenThread. Enable it with the [*]) this way will compile both Wi-Fi and Thread to the firmware, so increases the binary size.

@chshu I still have the same issue when just using this file unfortunately. (and not just enabling Thread via menuconfig) .

@chshu
Copy link
Collaborator

chshu commented Jul 18, 2024

@pavel808 could you please tryout these steps:

cd esp-matter/examples/light
cp sdkconfig.defaults.c6_thread sdkconfig.defaults.esp32c6
idf.py set-target esp32c6
idf.py build

I just double confirmed it worked in my environment.

@pavel808
Copy link
Author

@chshu My bad. I wasn't swapping it with the sdkconfig.defaults.esp32c6 file. I can confirm that it now works, even with my own application. Thank you for the help on this!

Regarding the Thread Border Router, one thing which is an issue is that each time the board is reset, it loses the connection with the Wi-Fi network and I must manually enter all the details again and start Thread. Is this the default behaviour? How can I get this to retain the connection each time it boots up and have the Thread network active without manual intervention do you know? Thanks.

@chshu
Copy link
Collaborator

chshu commented Jul 18, 2024

@chshu chshu closed this as completed Sep 6, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants