search

espressif / esp-matter

Espressif's SDK for Matter
Apache License 2.0
698 stars 157 forks source link

Commisioning issue with android CHIP-tool (CON-284) #218

Closed MartinPArmstrong closed 1 year ago

MartinPArmstrong commented 1 year ago

Hi.

I am unable to commison the device using the Android CHIP-tool. I am however, able to commsion using google home. Using a ESP32S3 with the ZAP-light example, the same issue remains on the other examples aswell.

I (24) boot: ESP-IDF v4.4.3-dirty 2nd stage bootloader
I (25) boot: compile time 02:00:20
I (25) boot: chip revision: 0
I (27) boot.esp32s3: Boot SPI Speed : 80MHz
I (32) boot.esp32s3: SPI Mode       : DIO
I (36) boot.esp32s3: SPI Flash Size : 4MB
I (41) boot: Enabling RNG early entropy source...
I (46) boot: Partition Table:
I (50) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 sec_cert         unknown          3f 06 0000d000 00003000
I (65) boot:  1 nvs              WiFi data        01 02 00010000 00006000
I (72) boot:  2 otadata          OTA data         01 00 00016000 00002000
I (80) boot:  3 phy_init         RF data          01 01 00018000 00001000
I (87) boot:  4 ota_0            OTA app          00 10 00020000 001e0000
I (95) boot:  5 ota_1            OTA app          00 11 00200000 001e0000
I (102) boot:  6 fctry            WiFi data        01 02 003e0000 00006000
I (110) boot: End of partition table
I (114) esp_image: segment 0: paddr=00020020 vaddr=3c0e0020 size=305b8h (198072) map
I (158) esp_image: segment 1: paddr=000505e0 vaddr=3fc97ca0 size=04b24h ( 19236) load
I (162) esp_image: segment 2: paddr=0005510c vaddr=40374000 size=0af0ch ( 44812) load
I (174) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=dd260h (905824) map
I (336) esp_image: segment 4: paddr=0013d288 vaddr=4037ef0c size=08d90h ( 36240) load
I (345) esp_image: segment 5: paddr=00146020 vaddr=50000000 size=00010h (    16) load
I (353) boot: Loaded app from partition at offset 0x20000
I (353) boot: Disabling RNG early entropy source...
I (365) cpu_start: Pro cpu up.
I (365) cpu_start: Starting app cpu, entry point is 0x40375458
0x40375458: call_start_cpu1 at /home/martin/esp-idf/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (379) cpu_start: Pro cpu start user code
I (379) cpu_start: cpu freq: 160000000
I (379) cpu_start: Application information:
I (382) cpu_start: Project name:     zap_light
I (387) cpu_start: App version:      v1.0
I (392) cpu_start: Compile time:     Feb  3 2023 02:00:16
I (398) cpu_start: ELF file SHA256:  b3ab3a573693aeb8...
I (404) cpu_start: ESP-IDF:          v4.4.3-dirty
I (409) heap_init: Initializing. RAM available for dynamic allocation:
I (417) heap_init: At 3FCACAA8 len 0003CC68 (243 KiB): D/IRAM
I (423) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (430) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (436) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
I (443) spi_flash: detected chip: generic
I (447) spi_flash: flash io: dio
W (451) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (465) sleep: Configure to isolate all GPIO pins in sleep state
I (471) sleep: Enable automatic switching of GPIO sleep configuration
I (478) coexist: coexist rom version e7ae62f
I (483) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (546) led_driver_ws2812: Initializing light driver
I (546) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (546) pp: pp rom version: e7ae62f
I (556) net80211: net80211 rom version: e7ae62f
I (566) wifi:wifi driver task: 3fceda58, prio:23, stack:6656, core=0
I (566) system_api: Base MAC address is not set
I (566) system_api: read default base MAC address from EFUSE
I (576) wifi:wifi firmware version: 8cb87ff
I (576) wifi:wifi certification version: v7.0
I (586) wifi:config NVS flash: enabled
I (586) wifi:config nano formating: disabled
I (586) wifi:Init data frame dynamic rx buffer num: 32
I (596) wifi:Init management frame dynamic rx buffer num: 32
I (596) wifi:Init management short buffer num: 32
I (606) wifi:Init dynamic tx buffer num: 32
I (606) wifi:Init static tx FG buffer num: 2
I (616) wifi:Init static rx buffer size: 1600
I (616) wifi:Init static rx buffer num: 10
I (616) wifi:Init dynamic rx buffer num: 32
I (626) wifi_init: rx ba win: 6
I (626) wifi_init: tcpip mbox: 32
I (636) wifi_init: udp mbox: 6
I (636) wifi_init: tcp mbox: 6
I (636) wifi_init: tcp tx win: 5744
I (646) wifi_init: tcp rx win: 5744
I (646) wifi_init: tcp mss: 1440
I (656) wifi_init: WiFi IRAM OP enabled
I (656) wifi_init: WiFi RX IRAM OP enabled
I (676) chip[DL]: NVS set: chip-counters/reboot-count = 2 (0x2)
I (676) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
W (676) BT_INIT: esp_bt_controller_mem_release not implemented, return OK
I (686) BT_INIT: BT controller compile version [421c279]
I (686) phy_init: phy_version 503,13653eb,Jun  1 2022,17:47:08
I (736) BT_INIT: Bluetooth MAC: 60:55:f9:f5:26:96

I (736) NimBLE: GAP procedure initiated: stop advertising.

I (736) CHIP[DL]: BLE host-controller synced
I (1236) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1236) NimBLE: GAP procedure initiated: advertise; 
I (1236) NimBLE: disc_mode=2
I (1236) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1246) NimBLE: 

I (1256) chip[DL]: CHIPoBLE advertising started
E (1256) chip[DL]: Long dispatch time: 581 ms, for event type 2
I (1266) chip[DL]: Starting ESP WiFi layer
I (1266) wifi:mode : sta (60:55:f9:f5:26:94)
I (1276) wifi:enable tsf
W (1276) wifi:Haven't to connect to a suitable AP now!
I (1276) chip[DL]: Done driving station state, nothing else to do...
W (1286) wifi:Haven't to connect to a suitable AP now!
I (1296) chip[DL]: Done driving station state, nothing else to do...
I (1296) chip[SVR]: Server initializing...
I (1306) chip[TS]: Last Known Good Time: 2023-02-03T02:03:56
I (1306) chip[DMG]: AccessControl: initializing
I (1316) chip[DMG]: Examples::AccessControlDelegate::Init
I (1316) chip[DMG]: AccessControl: setting
I (1326) chip[DMG]: DefaultAclStorage: initializing
I (1326) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1356) chip[ZCL]: Using ZAP configuration...
I (1356) chip[DMG]: AccessControlCluster: initializing
I (1356) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 0 **********
I (1366) chip[ZCL]: Initiating Admin Commissioning cluster.
I (1366) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0004's Attribute 0x0000 is 128 **********
I (1376) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0004's Attribute 0xFFFC is <invalid type: 0> **********
E (1396) chip[ZCL]: DeviceInfoProvider is not registered
I (1396) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x002C's Attribute 0x0001 is 0 **********
E (1406) chip[ZCL]: Trying to write invalid Calendar Type
E (1416) chip[ZCL]: Failed to write calendar type with error: 0x87
I (1416) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0x0000 is 128 **********
I (1436) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0xFFFC is <invalid type: 0> **********
I (1446) chip[ZCL]: On/Off set value: 1 0
I (1446) chip[ZCL]: On/off already set to new value
I (1456) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0000 is 1 **********
I (1466) led_driver_ws2812: led set r:0, g:0, b:0
I (1476) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x0007 is 0 **********
I (1476) led_driver_ws2812: led set r:0, g:0, b:0
I (1486) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x0008 is 2 **********
I (1496) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x4001 is 2 **********
I (1506) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0406's Attribute 0x0001 is 0 **********
I (1516) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0406's Attribute 0x0002 is 1 **********
I (1526) chip[DIS]: Updating services using commissioning mode 1
I (1536) chip[DIS]: CHIP minimal mDNS started advertising.
I (1546) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (1556) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: AC3C61DE894112A1.
I (1566) chip[DIS]: mDNS service published: _matterc._udp
I (1566) chip[IN]: CASE Server enabling CASE session setups
I (1576) chip[SVR]: Joining Multicast groups
I (1576) chip[SVR]: Server Listening...
E (1586) chip[DL]: Long dispatch time: 287 ms, for event type 2
I (1586) chip[DL]: WIFI_EVENT_STA_START
W (1596) wifi:Haven't to connect to a suitable AP now!
E (1596) esp_matter_core: Node does not exist or esp_matter does not start
I (1596) chip[DL]: Done driving station state, nothing else to do...
I (1616) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1626) chip[DL]: Device already advertising, stop active advertisement and restart
I (1636) NimBLE: GAP procedure initiated: stop advertising.

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

I (1656) app_main: Commissioning window opened
E (1666) app_main: Matter start failed: 259
I (1666) led_driver_ws2812: led set r:0, g:0, b:0
I (1676) led_driver_ws2812: led set r:0, g:0, b:0
I (1676) led_driver_ws2812: led set r:0, g:0, b:0
I (1686) led_driver_ws2812: led set r:0, g:0, b:0
> I (31536) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)
I (31536) chip[DL]: Device already advertising, stop active advertisement and restart
I (31546) NimBLE: GAP procedure initiated: stop advertising.

I (31546) NimBLE: GAP procedure initiated: advertise; 
I (31556) NimBLE: disc_mode=2
I (31556) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (31576) NimBLE: 

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

I (168846) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (168876) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (168876) chip[EM]: >>> [E:902r M:202845798] (U) Msg RX from 0:56B04672D9E74C08 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I (168886) chip[EM]: <<< [E:902r M:235431901] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I (168906) chip[IN]: (U) Sending msg 235431901 to IP address 'BLE'
I (168906) NimBLE: GATT procedure initiated: indicate; 
I (168916) NimBLE: att_handle=14

I (168996) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (169056) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (169056) chip[EM]: >>> [E:902r M:202845799] (U) Msg RX from 0:56B04672D9E74C08 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I (170056) chip[EM]: <<< [E:902r M:235431902] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I (170056) chip[IN]: (U) Sending msg 235431902 to IP address 'BLE'
I (170066) NimBLE: GATT procedure initiated: indicate; 
I (170066) NimBLE: att_handle=14

E (170086) chip[DL]: Long dispatch time: 1029 ms, for event type 7
I (170136) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (170196) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (170196) chip[EM]: >>> [E:902r M:202845800] (U) Msg RX from 0:56B04672D9E74C08 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I (170206) chip[EM]: <<< [E:902r M:235431903] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (170226) chip[IN]: (U) Sending msg 235431903 to IP address 'BLE'
I (170226) NimBLE: GATT procedure initiated: indicate; 
I (170236) NimBLE: att_handle=14

I (170236) chip[SC]: SecureSession[0x3fca16a0]: Moving from state 'kEstablishing' --> 'kActive'
I (170236) chip[SVR]: Commissioning completed session establishment step
I (170256) chip[DIS]: Updating services using commissioning mode 0
I (170256) chip[DIS]: CHIP minimal mDNS started advertising.
I (170266) chip[SVR]: Device completed Rendezvous process
I (170266) app_main: Commissioning session started
I (170276) app_main: Commissioning window closed
I (170286) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (170316) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (170316) chip[EM]: >>> [E:903r M:184985224] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
I (170336) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
I (170346) chip[EM]: <<< [E:903r M:61286790] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (170346) chip[IN]: (S) Sending msg 61286790 on secure session with LSID: 55944
I (170356) NimBLE: GATT procedure initiated: indicate; 
I (170366) NimBLE: att_handle=14

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

I (170526) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (170556) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (170556) chip[EM]: >>> [E:904r M:184985225] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I (170566) chip[FS]: GeneralCommissioning: Received ArmFailSafe (30s)
I (170576) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 3 **********
I (170586) chip[EM]: <<< [E:904r M:61286791] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (170596) chip[IN]: (S) Sending msg 61286791 on secure session with LSID: 55944
I (170596) NimBLE: GATT procedure initiated: indicate; 
I (170616) NimBLE: att_handle=14

I (170676) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (170706) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (170706) chip[EM]: >>> [E:905r M:184985226] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I (170716) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
I (170736) chip[DL]: NVS set: chip-config/country-code = "XX"
I (170736) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 4 **********
I (170746) chip[EM]: <<< [E:905r M:61286792] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (170756) chip[IN]: (S) Sending msg 61286792 on secure session with LSID: 55944
I (170766) NimBLE: GATT procedure initiated: indicate; 
I (170776) NimBLE: att_handle=14

I (170826) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (170856) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (170856) chip[EM]: >>> [E:906r M:184985227] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I (170866) chip[ZCL]: OpCreds: Certificate Chain request received for PAI
I (170876) chip[EM]: <<< [E:906r M:61286793] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (170886) chip[IN]: (S) Sending msg 61286793 on secure session with LSID: 55944
I (170886) NimBLE: GATT procedure initiated: indicate; 
I (170906) NimBLE: att_handle=14

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

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

I (171126) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (171156) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (171156) chip[EM]: >>> [E:907r M:184985228] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I (171166) chip[ZCL]: OpCreds: Certificate Chain request received for DAC
I (171176) chip[EM]: <<< [E:907r M:61286794] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (171186) chip[IN]: (S) Sending msg 61286794 on secure session with LSID: 55944
I (171186) NimBLE: GATT procedure initiated: indicate; 
I (171206) NimBLE: att_handle=14

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

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

I (171426) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (171456) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (171456) chip[EM]: >>> [E:908r M:184985229] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I (171466) chip[ZCL]: OpCreds: Received an AttestationRequest command
I (171676) chip[ZCL]: OpCreds: AttestationRequest successful.
I (171686) chip[EM]: <<< [E:908r M:61286795] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (171686) chip[IN]: (S) Sending msg 61286795 on secure session with LSID: 55944
I (171696) NimBLE: GATT procedure initiated: indicate; 
I (171696) NimBLE: att_handle=14

E (171706) chip[DL]: Long dispatch time: 256 ms, for event type 7
I (171786) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (171786) NimBLE: GATT procedure initiated: indicate; 
I (171796) NimBLE: att_handle=14

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

I (171966) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (172056) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (172056) chip[EM]: >>> [E:909r M:184985230] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I (172066) chip[FS]: GeneralCommissioning: Received ArmFailSafe (0s)
I (172066) chip[FS]: Fail-safe timer expired
I (172086) chip[EM]: <<< [E:909r M:61286796] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (172086) chip[IN]: (S) Sending msg 61286796 on secure session with LSID: 55944
I (172096) NimBLE: GATT procedure initiated: indicate; 
I (172096) NimBLE: att_handle=14

E (172116) chip[SVR]: Failsafe timer expired
I (172116) chip[SC]: SecureSession[0x3fca16a0]: Moving from state 'kActive' --> 'kPendingEviction'
E (172126) chip[SVR]: Commissioning failed (attempt 1): 32
I (172126) chip[BLE]: Releasing end point's BLE connection back to application.
I (172146) chip[DIS]: Updating services using commissioning mode 1
I (172146) chip[DIS]: CHIP minimal mDNS started advertising.
I (172156) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (172156) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: AC3C61DE894112A1.
I (172176) chip[DIS]: mDNS service published: _matterc._udp
E (172186) chip[ZCL]: OpCreds: Got FailSafeTimerExpired
E (172186) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
I (172196) chip[TS]: Pending Last Known Good Time: 2023-02-03T02:03:56
I (172176) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (172216) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0
I (172226) chip[DL]: CHIPoBLE unsubscribe received
I (172196) chip[TS]: Previous Last Known Good Time: 2023-02-03T02:03:56
I (172236) chip[TS]: Reverted Last Known Good Time to previous value
I (172236) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 0 **********
I (172256) app_main: Commissioning failed, fail safe timer expired
E (172266) chip[DL]: Long dispatch time: 150 ms, for event type 32782
I (172266) chip[FS]: Fail-safe cleanly disarmed
I (172266) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (172276) NimBLE: GAP procedure initiated: advertise; 
I (172276) NimBLE: disc_mode=2
I (172286) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (172306) NimBLE: 

I (172306) chip[DL]: CHIPoBLE advertising started
I (172306) app_main: Commissioning window opened
E (172316) chip[BLE]: no endpoint for BLE sent data ack
E (172316) chip[BLE]: no endpoint for unsub recvd
I (173166) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213)
I (173166) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (173176) chip[DL]: Device already advertising, stop active advertisement and restart
I (173176) NimBLE: GAP procedure initiated: stop advertising.

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

I (202146) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)
I (202146) chip[DL]: Device already advertising, stop active advertisement and restart
I (202156) NimBLE: GAP procedure initiated: stop advertising.

I (202156) NimBLE: GAP procedure initiated: advertise; 
I (202166) NimBLE: disc_mode=2
I (202166) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (202186) NimBLE:
jonsmirl commented 1 year ago

Android CHIPTool is not maintained very well and it is broken much of the time. Try GSAFM instead... https://github.com/google-home/sample-app-for-matter-android

dhrishi commented 1 year ago

@MartinPArmstrong As per the logs, the CSR (after the attestation request is successful) request is not received from the commissioner and hence the fail safe timer expires and the commissioning fails. Is it possible to check using other commissioners like host-based chip-tool, Google Home, Apple Home or the custom Android app as mentioned by @jonsmirl above?

MartinPArmstrong commented 1 year ago

Thanks for the clarification. It does indeed work with both the standard Google Home app, as well as the custom one mentioned above. Il consider this solved and close the issue.