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

Not a Matter-certified device #93

Closed
edWin-m opened this issue Mar 2, 2023 · 13 comments
Closed

Not a Matter-certified device #93

edWin-m opened this issue Mar 2, 2023 · 13 comments

Comments

@edWin-m
Copy link
Contributor

edWin-m commented Mar 2, 2023

This device can't be set up or controlled with Google.

I was using this device recently (less than 24 hours ago) without this issue in GHSAFM. I can still commission it using the chip-tool in a terminal and Apple Home seems to be working well too. I have attached the device logs showing the matter config and the commissioning error.

Version

Commit - 0eb3c6d2c126c020619d3fe40026c9fa52e1c80c

Device Error Log with GHSAFM as Commissioner

I (62538) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (62538) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (62548) chip[EM]: >>> [E:26846r M:247894512] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I (62568) esp_matter_command: Received command 0x0004 for enpoint 0x0000's cluster 0x0000003E
I (62568) chip[ZCL]: OpCreds: Received a CSRRequest command
I (62918) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded
I (63088) chip[ZCL]: OpCreds: CSRRequest successful.
I (63088) chip[EM]: <<< [E:26846r M:64238810] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (63108) chip[IN]: (S) Sending msg 64238810 on secure session with LSID: 40484
I (63108) NimBLE: GATT procedure initiated: indicate; 
I (63118) NimBLE: att_handle=14

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

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

I (63348) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (65198) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0
I (65198) chip[DL]: CHIPoBLE unsubscribe received
I (65208) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213)
I (65198) chip[BLE]: Releasing end point's BLE connection back to application.

Matter Device Config (ESP32)

I (76569) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0005's Attribute 0x0003 is 0 **********
I (76569) chip[EM]: <<< [E:22868r M:211225918 (Ack:72764337)] (S) Msg TX to 1:000000000001B669 [2653] --- Type 0001:09 (IM:InvokeCommandResponse)
I (76579) chip[IN]: (S) Sending msg 211225918 on secure session with LSID: 267
E (76599) chip[DL]: Long dispatch time: 127 ms, for event type 3
I (76609) chip[EM]: >>> [E:22868r M:72764338 (Ack:211225918)] (S) Msg RX from 1:000000000001B669 [2653] --- Type 0000:10 (SecureChannel:StandaloneAck)

> matter config
VendorId:        65521 (0xFFF1)
ProductId:       32768 (0x8000)
HardwareVersion: 0 (0x0)
PinCode:         20202021
Discriminator:   f00
Done
@pierredelisle
Copy link
Contributor

@edWin-m
Copy link
Contributor Author

edWin-m commented Mar 3, 2023

@pierredelisle I can't access the device logs at this moment. I have included all the info I can provide at this moment below. Please let me know if there is anything else you need.

GHSAFM version

  • version name - v1.3.0
  • commit - 0eb3c6d2c126c020619d3fe40026c9fa52e1c80c

Test Device

Google Play Services version

  • version - 230617065
% adb shell dumpsys activity provider com.google.android.gms.chimera.container.GmsModuleProvider | grep -E '(policy|optional)_home'
        com.google.android.gms.optional_home [230617065] [23.06.17 (100400-0)] [Download:000001b8/dl-Home.optional_230617100400.apk] [download:/Home.optional/230617100400:Home.optional:230617100400]
% 

Phone logs

@KhushbuShah25
Copy link

Facing same issue. It was working fine but from tomorrow, sample app is showing "Not a Matter--certified device" error.

@edWin-m
Copy link
Contributor Author

edWin-m commented Mar 3, 2023

It looks like the device is failing attestation. I still can't figure out why.

03-03 09:15:42.615 24520 24520 E SetupDeviceViewModel: Commissioning failed with state Attestation failure. [CONTEXT service_id=336 ]
03-03 09:15:42.615 24520 24520 E SetupDeviceViewModel: m.emi: Device did not pass attestation (error(s)=[3])
03-03 09:15:42.615 24520 24520 E SetupDeviceViewModel: 	at m.enl.g(:com.google.android.gms.optional_home@230617065@23.06.17 (100400-0):36)
03-03 09:15:42.615 24520 24520 E SetupDeviceViewModel: 	at m.enf.b(:com.google.android.gms.optional_home@230617065@23.06.17 (100400-0):0)
03-03 09:15:42.615 24520 24520 E SetupDeviceViewModel: 	at m.nog.f(:com.google.android.gms.optional_home@230617065@23.06.17 (100400-0):4)
03-03 09:15:42.615 24520 24520 E SetupDeviceViewModel: 	at m.nvq.run(:com.google.android.gms.optional_home@230617065@23.06.17 (100400-0):8)

@aggaddam
Copy link

aggaddam commented Mar 3, 2023

I am also facing the same issue (Unable to commission the device, shows error - "Not a certified matter device") with the GHSAFM test app this week. But with Chip tool it works fine without any issues

Earlier, I was able to commission the device with Google Home Sample App for Matter (GHSAFM) without any issues with the color temperature light example with ESP32 C3 hardware.

Here is the device log file

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x1 (POWERON),boot:0xd (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd6100,len:0x16bc
load:0x403ce000,len:0x930
load:0x403d0000,len:0x2d28
entry 0x403ce000
I (30) boot: ESP-IDF cf637563-dirty 2nd stage bootloader
I (30) boot: compile time 15:00:28
I (30) boot: chip revision: 3
I (32) boot.esp32c3: SPI Speed      : 80MHz
I (37) boot.esp32c3: SPI Mode       : DIO
I (42) boot.esp32c3: SPI Flash Size : 4MB
I (47) boot: Enabling RNG early entropy source...
I (52) boot: Partition Table:
I (56) boot: ## Label            Usage          Type ST Offset   Length
I (63) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
I (70) boot:  1 nvs              WiFi data        01 02 00010000 00006000
I (78) boot:  2 nvs_keys         NVS keys         01 04 00016000 00001000
I (85) boot:  3 otadata          OTA data         01 00 00017000 00002000
I (93) boot:  4 phy_init         RF data          01 01 00019000 00001000
I (100) boot:  5 ota_0            OTA app          00 10 00020000 001e0000
I (108) boot:  6 ota_1            OTA app          00 11 00200000 001e0000
I (115) boot:  7 fctry            WiFi data        01 02 003e0000 00006000
I (123) boot: End of partition table
I (127) boot: No factory image, trying OTA 0
I (132) esp_image: segment 0: paddr=00020020 vaddr=3c100020 size=30330h (197424) map
I (172) esp_image: segment 1: paddr=00050358 vaddr=3fc90400 size=03720h ( 14112) load
I (174) esp_image: segment 2: paddr=00053a80 vaddr=40380000 size=0c598h ( 50584) load
I (187) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=f183ch (989244) map
I (341) esp_image: segment 4: paddr=00151864 vaddr=4038c598 size=03c9ch ( 15516) load
I (344) esp_image: segment 5: paddr=00155508 vaddr=50000010 size=00010h (    16) load
I (352) boot: Loaded app from partition at offset 0x20000
I (395) boot: Set actual ota_seq=1 in otadata[0]
I (395) boot: Disabling RNG early entropy source...
I (406) cpu_start: Pro cpu up.
D (406) efuse: In EFUSE_BLK2__DATA4_REG is used 3 bits starting with 0 bit
D (406) efuse: In EFUSE_BLK2__DATA4_REG is used 8 bits starting with 12 bit
D (413) efuse: In EFUSE_BLK1__DATA3_REG is used 3 bits starting with 18 bit
D (420) efuse: In EFUSE_BLK1__DATA5_REG is used 5 bits starting with 5 bit
D (426) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 7 bit
D (433) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 14 bit
D (440) efuse: In EFUSE_BLK1__DATA4_REG is used 8 bits starting with 21 bit
D (447) efuse: In EFUSE_BLK1__DATA4_REG is used 3 bits starting with 29 bit
D (454) efuse: In EFUSE_BLK1__DATA5_REG is used 5 bits starting with 0 bit
D (469) clk: RTC_SLOW_CLK calibration value: 3786598
I (478) cpu_start: Pro cpu start user code
I (478) cpu_start: cpu freq: 160000000
I (478) cpu_start: Application information:
I (481) cpu_start: Project name:     light
I (485) cpu_start: App version:      v1.0
I (490) cpu_start: Compile time:     Mar  2 2023 15:00:24
I (496) cpu_start: ELF file SHA256:  130c93c0f41db7f9...
I (502) cpu_start: ESP-IDF:          cf637563-dirty
D (508) memory_layout: Checking 4 reserved memory ranges:
D (513) memory_layout: Reserved memory range 0x3fc80000 - 0x3fc90400
D (520) memory_layout: Reserved memory range 0x3fc90400 - 0x3fca3e60
D (526) memory_layout: Reserved memory range 0x3fcdf060 - 0x3fce0000
D (533) memory_layout: Reserved memory range 0x50000000 - 0x50000020
D (539) memory_layout: Building list of available memory regions:
D (545) memory_layout: Available memory region 0x3fca3e60 - 0x3fcc0000
D (552) memory_layout: Available memory region 0x3fcc0000 - 0x3fcdf060
D (558) memory_layout: Available memory region 0x50000020 - 0x50002000
I (565) heap_init: Initializing. RAM available for dynamic allocation:
D (572) heap_init: New heap initialised at 0x3fca3e60
I (577) heap_init: At 3FCA3E60 len 0001C1A0 (112 KiB): DRAM
I (583) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM
D (590) heap_init: New heap initialised at 0x50000020
I (595) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM
D (602) FLASH_HAL: extra_dummy: 0
D (605) spi_flash: trying chip: issi
D (609) spi_flash: trying chip: gd
D (612) spi_flash: trying chip: mxic
D (616) spi_flash: trying chip: winbond
D (620) spi_flash: trying chip: boya
D (623) spi_flash: trying chip: th
D (627) spi_flash: trying chip: generic
I (631) spi_flash: detected chip: generic
I (636) spi_flash: flash io: dio
D (639) cpu_start: calling init function: 0x420e0892
D (644) cpu_start: calling init function: 0x420e0796
D (649) cpu_start: calling init function: 0x420e0210
D (654) cpu_start: calling init function: 0x420e002a
D (659) cpu_start: calling init function: 0x420d1310
D (665) efuse: In EFUSE_BLK2__DATA4_REG is used 3 bits starting with 0 bit
D (671) efuse: In EFUSE_BLK2__DATA5_REG is used 10 bits starting with 18 bit
D (679) cpu_start: calling init function: 0x42099458
D (684) cpu_start: calling init function: 0x42095654
D (689) cpu_start: calling init function: 0x42062b84
D (694) cpu_start: calling init function: 0x42061902
D (699) cpu_start: calling init function: 0x420607f0
D (704) cpu_start: calling init function: 0x4205fa90
D (709) cpu_start: calling init function: 0x4205f768
D (714) cpu_start: calling init function: 0x42058af2
D (719) cpu_start: calling init function: 0x4205780a
D (724) cpu_start: calling init function: 0x4205208c
D (729) cpu_start: calling init function: 0x42050b94
D (734) cpu_start: calling init function: 0x4202d902
D (739) cpu_start: calling init function: 0x4202cdd8
D (744) cpu_start: calling init function: 0x4202c646
D (749) cpu_start: calling init function: 0x4202c230
D (754) cpu_start: calling init function: 0x4202c0d8
D (759) cpu_start: calling init function: 0x4202acde
D (764) cpu_start: calling init function: 0x4202a9e0
D (769) cpu_start: calling init function: 0x420288ce
D (774) cpu_start: calling init function: 0x42026f4c
D (779) cpu_start: calling init function: 0x420264b8
D (784) cpu_start: calling init function: 0x42025e58
D (789) cpu_start: calling init function: 0x42025c8a
D (794) cpu_start: calling init function: 0x420257ee
D (799) cpu_start: calling init function: 0x4202359e
D (804) cpu_start: calling init function: 0x42022b82
D (809) cpu_start: calling init function: 0x42022732
D (814) cpu_start: calling init function: 0x4202208c
D (819) cpu_start: calling init function: 0x42021c64
D (825) cpu_start: calling init function: 0x4201fcda
D (830) cpu_start: calling init function: 0x420185b8
D (835) cpu_start: calling init function: 0x42013b3e
D (840) cpu_start: calling init function: 0x4200d6d4
D (845) cpu_start: calling init function: 0x4200a110
D (850) cpu_start: calling init function: 0x4200002a
D (855) intr_alloc: Connected src 39 to int 2 (cpu 0)
I (860) sleep: Configure to isolate all GPIO pins in sleep state
I (867) sleep: Enable automatic switching of GPIO sleep configuration
I (874) coexist: coexist rom version 9387209
D (879) intr_alloc: Connected src 50 to int 3 (cpu 0)
I (884) cpu_start: Starting scheduler.
D (888) intr_alloc: Connected src 37 to int 4 (cpu 0)
D (888) heap_init: New heap initialised at 0x3fcc0000
D (893) intr_alloc: Connected src 33 to int 7 (cpu 0)
D (898) partition: Loading the partition table
D (903) partition: Partition table MD5 verified
I (911) led_driver_ws2812: Initializing light driver
D (913) rmt: rmt_source_clk_hz: 80000000

D (917) rmt: Rmt Tx Channel 0|Gpio 8|Sclk_Hz 80000000|Div 2|Carrier_Hz 38000|Duty 33
D (925) intr_alloc: Connected src 28 to int 9 (cpu 0)
D (930) rmt: RMT translator init done
I (934) gpio: GPIO[9]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
D (943) esp_matter_core: Set val called with string with size 0
D (949) esp_matter_core: Set val called with string with size 0
D (955) esp_matter_core: Set val called with string with size 0
D (961) esp_matter_core: Set val called with string with size 0
D (967) esp_matter_core: Set val called with string with size 0
D (973) nvs: nvs_open_from_partition endpoint_0 0
D (977) esp_matter_core: Set val called with string with size 0
D (983) nvs: nvs_open_from_partition endpoint_0 1
D (989) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x28, attribute_id-0x6
D (997) nvs: nvs_close 1
D (1000) esp_matter_core: Set val called with string with size 0
D (1006) esp_matter_core: Set val called with string with size 0
D (1012) esp_matter_core: Set val called with string with size 0
D (1018) esp_matter_core: Set val called with string with size 0
D (1024) esp_matter_core: Set val called with string with size 0
D (1031) nvs: nvs_open_from_partition endpoint_0 0
D (1035) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x28, attribute_id-0x5
D (1045) nvs: nvs_get_str_or_blob 28:5
D (1048) nvs: nvs_close 2
D (1051) nvs: nvs_open_from_partition endpoint_0 1
D (1056) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x28, attribute_id-0x5
D (1065) nvs: nvs_set_blob 28:5 32
D (1069) nvs: nvs_close 3
D (1072) esp_matter_core: Set val called with string with size 0
D (1078) esp_matter_core: Set val called with string with size 0
D (1084) nvs: nvs_open_from_partition endpoint_0 0
D (1088) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x31, attribute_id-0x4
D (1098) nvs: nvs_get_str_or_blob 31:4
D (1101) nvs: nvs_close 4
D (1104) nvs: nvs_open_from_partition endpoint_0 1
D (1109) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x31, attribute_id-0x4
D (1118) nvs: nvs_set_blob 31:4 24
D (1123) nvs: nvs_close 5
D (1125) esp_matter_core: Set val called with string with size 0
D (1131) esp_matter_core: Set val called with string with size 0
D (1137) nvs: nvs_open_from_partition endpoint_0 0
D (1142) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x33, attribute_id-0x1
D (1151) nvs: nvs_get_str_or_blob 33:1
D (1155) nvs: nvs_close 6
D (1157) nvs: nvs_open_from_partition endpoint_0 1
D (1162) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x33, attribute_id-0x1
D (1171) nvs: nvs_set_blob 33:1 24
D (1176) nvs: nvs_close 7
D (1178) nvs: nvs_open_from_partition endpoint_0 0
D (1182) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x0
D (1192) nvs: nvs_get_str_or_blob 3E:0
D (1196) nvs: nvs_close 8
D (1198) esp_matter_core: Set val called with string with size 0
D (1204) nvs: nvs_open_from_partition endpoint_0 1
D (1209) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x0
D (1218) nvs: nvs_close 9
D (1221) nvs: nvs_open_from_partition endpoint_0 0
D (1226) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x3
D (1235) nvs: nvs_get_str_or_blob 3E:3
D (1239) nvs: nvs_close 10
D (1242) nvs: nvs_open_from_partition endpoint_0 1
D (1247) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x3
D (1256) nvs: nvs_set_blob 3E:3 24
D (1260) nvs: nvs_close 11
D (1262) nvs: nvs_open_from_partition endpoint_0 0
D (1267) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x1
D (1276) nvs: nvs_get_str_or_blob 3E:1
D (1280) nvs: nvs_close 12
D (1283) esp_matter_core: Set val called with string with size 0
D (1289) nvs: nvs_open_from_partition endpoint_0 1
D (1294) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x1
D (1303) nvs: nvs_close 13
D (1306) nvs: nvs_open_from_partition endpoint_0 0
D (1311) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x4
D (1320) nvs: nvs_get_str_or_blob 3E:4
D (1324) nvs: nvs_close 14
D (1327) esp_matter_core: Set val called with string with size 0
D (1333) nvs: nvs_open_from_partition endpoint_0 1
D (1338) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x4
D (1347) nvs: nvs_close 15
D (1350) nvs: nvs_open_from_partition endpoint_0 0
D (1355) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3f, attribute_id-0x0
D (1364) nvs: nvs_get_str_or_blob 3F:0
D (1368) nvs: nvs_close 16
D (1371) esp_matter_core: Set val called with string with size 0
D (1377) nvs: nvs_open_from_partition endpoint_0 1
D (1381) esp_matter_core: strore attribute in nvs: endpoint_id-0x0, cluster_id-0x3f, attribute_id-0x0
D (1391) nvs: nvs_close 17
D (1394) esp_matter_core: Set val called with string with size 0
D (1400) esp_matter_core: Set val called with string with size 0
D (1406) esp_matter_core: Set val called with string with size 0
D (1412) esp_matter_core: Set val called with string with size 0
D (1418) esp_matter_core: Set val called with string with size 0
D (1424) esp_matter_core: Set val called with string with size 0
D (1431) nvs: nvs_open_from_partition endpoint_1 0
D (1435) nvs: nvs_open_from_partition endpoint_1 1
D (1440) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x6, attribute_id-0x0
D (1449) nvs: nvs_set_blob 6:0 24
D (1453) nvs: nvs_close 18
D (1455) nvs: nvs_open_from_partition endpoint_1 0
D (1460) esp_matter_core: read attribute from nvs: endpoint_id-0x1, cluster_id-0x6, attribute_id-0x4003
D (1469) nvs: nvs_get_str_or_blob 6:4003
D (1473) nvs: nvs_close 19
D (1476) nvs: nvs_open_from_partition endpoint_1 1
D (1481) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x6, attribute_id-0x4003
D (1491) nvs: nvs_set_blob 6:4003 24
D (1495) nvs: nvs_close 20
D (1497) nvs: nvs_open_from_partition endpoint_1 0
D (1502) esp_matter_core: read attribute from nvs: endpoint_id-0x1, cluster_id-0x8, attribute_id-0x0
D (1511) nvs: nvs_get_str_or_blob 8:0
D (1515) nvs: nvs_close 21
D (1518) nvs: nvs_open_from_partition endpoint_1 1
D (1522) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x8, attribute_id-0x0
D (1532) nvs: nvs_set_blob 8:0 24
D (1536) nvs: nvs_close 22
D (1538) nvs: nvs_open_from_partition endpoint_1 0
D (1543) esp_matter_core: read attribute from nvs: endpoint_id-0x1, cluster_id-0x8, attribute_id-0x4000
D (1552) nvs: nvs_get_str_or_blob 8:4000
D (1556) nvs: nvs_close 23
D (1559) nvs: nvs_open_from_partition endpoint_1 1
D (1564) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x8, attribute_id-0x4000
D (1573) nvs: nvs_set_blob 8:4000 24
D (1577) nvs: nvs_close 24
D (1580) nvs: nvs_open_from_partition endpoint_1 0
D (1584) esp_matter_core: read attribute from nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x8
D (1594) nvs: nvs_get_str_or_blob 300:8
D (1598) nvs: nvs_close 25
D (1601) nvs: nvs_open_from_partition endpoint_1 1
D (1605) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x8
D (1615) nvs: nvs_set_blob 300:8 24
D (1619) nvs: nvs_close 26
D (1621) nvs: nvs_open_from_partition endpoint_1 0
D (1626) esp_matter_core: read attribute from nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x4001
D (1636) nvs: nvs_get_str_or_blob 300:4001
D (1640) nvs: nvs_close 27
D (1643) nvs: nvs_open_from_partition endpoint_1 1
D (1647) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x4001
D (1657) nvs: nvs_set_blob 300:4001 24
D (1661) nvs: nvs_close 28
D (1664) nvs: nvs_open_from_partition endpoint_1 0
D (1668) esp_matter_core: read attribute from nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x7
D (1678) nvs: nvs_get_str_or_blob 300:7
D (1682) nvs: nvs_close 29
D (1685) nvs: nvs_open_from_partition endpoint_1 1
D (1689) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x7
D (1699) nvs: nvs_set_blob 300:7 24
D (1703) nvs: nvs_close 30
I (1705) app_main: Light created with endpoint_id 1
D (1711) nvs: nvs_open_from_partition endpoint_1 0
D (1715) esp_matter_core: read attribute from nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x0
D (1725) nvs: nvs_get_str_or_blob 300:0
D (1729) nvs: nvs_close 31
D (1732) nvs: nvs_open_from_partition endpoint_1 1
D (1736) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x0
D (1746) nvs: nvs_set_blob 300:0 24
D (1750) nvs: nvs_close 32
D (1752) nvs: nvs_open_from_partition endpoint_1 0
D (1757) esp_matter_core: read attribute from nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x1
D (1766) nvs: nvs_get_str_or_blob 300:1
D (1770) nvs: nvs_close 33
D (1773) nvs: nvs_open_from_partition endpoint_1 1
D (1778) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x300, attribute_id-0x1
D (1787) nvs: nvs_set_blob 300:1 24
D (1791) nvs: nvs_close 34
W (1794) esp_matter_core: Command 0x0047 on cluster 0x0300 already exists. Not creating again.
D (1803) esp_netif_lwip: LwIP stack has been initialized
D (1808) esp_netif_lwip: esp-netif has been successfully initialized
D (1815) event: running task for loop 0x3fcac304
D (1819) event: created task for loop 0x3fcac304
D (1824) event: created event loop 0x3fcac304
D (1829) esp_netif_objects: esp_netif_add_to_list 0x3fcad22c
D (1834) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1)
D (1843) esp_netif_objects: esp_netif_add_to_list 0x3fcad5f4
D (1848) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 2)
I (1857) pp: pp rom version: 9387209
I (1861) net80211: net80211 rom version: 9387209
D (1867) nvs: nvs_open_from_partition misc 1
I (1872) wifi:wifi driver task: 3fcafebc, prio:23, stack:6656, core=0
I (1877) system_api: Base MAC address is not set
I (1882) system_api: read default base MAC address from EFUSE
D (1889) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1896) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1903) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1910) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1917) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1924) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1931) nvs: nvs_open_from_partition nvs.net80211 1
D (1936) nvs: nvs_get opmode 1
D (1939) nvs: nvs_get_str_or_blob sta.ssid
D (1943) nvs: nvs_get sta.authmode 1
D (1947) nvs: nvs_get_str_or_blob sta.pswd
D (1951) nvs: nvs_get_str_or_blob sta.pmk
D (1955) nvs: nvs_get sta.chan 1
D (1959) nvs: nvs_get auto.conn 1
D (1962) nvs: nvs_get bssid.set 1
D (1965) nvs: nvs_get_str_or_blob sta.bssid
D (1970) nvs: nvs_get sta.lis_intval 2
D (1973) nvs: nvs_get sta.phym 1
D (1977) nvs: nvs_get sta.phybw 1
D (1980) nvs: nvs_get_str_or_blob sta.apsw
D (1984) nvs: nvs_get_str_or_blob sta.apinfo
D (1989) nvs: nvs_get sta.scan_method 1
D (1992) nvs: nvs_get sta.sort_method 1
D (1996) nvs: nvs_get sta.minrssi 1
D (2000) nvs: nvs_get sta.minauth 1
D (2004) nvs: nvs_get sta.pmf_e 1
D (2007) nvs: nvs_get sta.pmf_r 1
D (2010) nvs: nvs_get sta.btm_e 1
D (2014) nvs: nvs_get sta.rrm_e 1
D (2017) nvs: nvs_get sta.mbo_e 1
D (2020) nvs: nvs_get_str_or_blob ap.ssid
D (2025) nvs: nvs_get_str_or_blob ap.passwd
D (2029) nvs: nvs_get_str_or_blob ap.pmk
D (2033) nvs: nvs_get ap.chan 1
D (2036) nvs: nvs_get ap.authmode 1
D (2040) nvs: nvs_get ap.hidden 1
D (2043) nvs: nvs_get ap.max.conn 1
D (2046) nvs: nvs_get bcn.interval 2
D (2050) nvs: nvs_get ap.phym 1
D (2053) nvs: nvs_get ap.phybw 1
D (2057) nvs: nvs_get ap.sndchan 1
D (2060) nvs: nvs_get ap.pmf_e 1
D (2063) nvs: nvs_get ap.pmf_r 1
D (2067) nvs: nvs_get ap.p_cipher 1
D (2070) nvs: nvs_get lorate 1
D (2073) nvs: nvs_get_str_or_blob country
D (2077) nvs: nvs_get ap.ftm_r 1
D (2081) nvs: nvs_set ap.sndchan 1 1
I (2085) wifi:wifi firmware version: eeaa27d
I (2088) wifi:wifi certification version: v7.0
I (2093) wifi:config NVS flash: enabled
I (2096) wifi:config nano formating: disabled
I (2100) wifi:Init data frame dynamic rx buffer num: 32
I (2105) wifi:Init management frame dynamic rx buffer num: 32
I (2111) wifi:Init management short buffer num: 32
I (2115) wifi:Init dynamic tx buffer num: 32
I (2119) wifi:Init static tx FG buffer num: 2
I (2123) wifi:Init static rx buffer size: 1600
I (2127) wifi:Init static rx buffer num: 10
I (2131) wifi:Init dynamic rx buffer num: 32
I (2136) wifi_init: rx ba win: 6
I (2139) wifi_init: tcpip mbox: 32
I (2143) wifi_init: udp mbox: 6
I (2147) wifi_init: tcp mbox: 6
I (2151) wifi_init: tcp tx win: 5744
I (2155) wifi_init: tcp rx win: 5744
I (2159) wifi_init: tcp mss: 1440
I (2163) wifi_init: WiFi IRAM OP enabled
I (2168) wifi_init: WiFi RX IRAM OP enabled
D (2174) gdma: new group (0) at 0x3fcb59a0
D (2177) gdma: new pair (0,0) at 0x3fcb59cc
D (2181) gdma: new tx channel (0,0) at 0x3fcb5970
D (2186) gdma: new rx channel (0,0) at 0x3fcb59ec
D (2191) gdma: tx channel (0,0), (1:16) bytes aligned, burst enabled
D (2197) gdma: rx channel (0,0), (1:16) bytes aligned, burst disabled
D (2205) nvs: nvs_open_from_partition chip-factory 0
D (2209) nvs: nvs_open_from_partition chip-factory 1
D (2214) nvs: nvs_close 37
D (2217) nvs: nvs_open_from_partition chip-config 0
D (2222) nvs: nvs_open_from_partition chip-config 1
D (2227) nvs: nvs_close 38
D (2229) nvs: nvs_open_from_partition chip-counters 0
D (2234) nvs: nvs_open_from_partition chip-counters 1
D (2240) nvs: nvs_close 39
D (2243) nvs: nvs_open_from_partition chip-counters 1
D (2247) nvs: nvs_set reboot-count 4 1
I (2252) chip[DL]: NVS set: chip-counters/reboot-count = 1 (0x1)
D (2258) nvs: nvs_close 40
D (2261) nvs: nvs_open_from_partition chip-counters 1
D (2266) nvs: nvs_set total-hours 4 0
I (2270) chip[DL]: NVS set: chip-counters/total-hours = 0 (0x0)
D (2276) nvs: nvs_close 41
D (2279) nvs: nvs_open_from_partition chip-config 0
D (2284) nvs: nvs_get_str_or_blob unique-id
D (2288) nvs: nvs_close 42
D (2291) nvs: nvs_open_from_partition chip-config 1
D (2296) nvs: nvs_set_str unique-id F5F39C2F9146734F
I (2302) chip[DL]: NVS set: chip-config/unique-id = "F5F39C2F9146734F"
D (2308) nvs: nvs_close 43
I (2311) chip[DL]: Changing ESP WiFi mode: AP -> STA+AP
D (2317) nvs: nvs_set opmode 1 3
I (2321) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA
D (2326) nvs: nvs_set opmode 1 1
I (2330) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
D (2338) chip[DL]: CHIP task running
W (2341) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK
I (2349) BTDM_INIT: BT controller compile version [05195c9]
I (2355) phy_init: phy_version 912,d001756,Jun  2 2022,16:28:07
D (2361) phy_init: loading PHY init data from application binary
D (2367) nvs: nvs_open_from_partition phy 0
D (2372) phy_init: esp_phy_load_cal_data_from_nvs: failed to open NVS namespace (0x1102)
W (2380) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
D (2389) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (2396) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (2403) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (2410) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (2417) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (2425) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (2459) nvs: nvs_open_from_partition phy 1
D (2460) nvs: nvs_set_blob cal_data 1904
D (2466) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (2467) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (2470) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (2477) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (2485) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (2492) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (2499) nvs: nvs_set_blob cal_mac 6
D (2503) nvs: nvs_set cal_version 4 912
D (2507) nvs: nvs_close 44
I (2510) BTDM_INIT: Bluetooth MAC: 34:b4:72:74:64:d2

D (2516) CHIP[DL]: BLE Host Task Started
I (2521) NimBLE: GAP procedure initiated: stop advertising.

I (2526) CHIP[DL]: BLE host-controller synced
D (3031) nvs: nvs_open_from_partition chip-factory 0
D (3031) nvs: nvs_get discriminator 4
D (3031) nvs: nvs_close 45
D (3032) nvs: nvs_open_from_partition chip-factory 0
D (3036) nvs: nvs_get discriminator 4
D (3040) nvs: nvs_close 46
D (3043) CHIP[DL]: NimBLE start advertising...
I (3048) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (3056) NimBLE: GAP procedure initiated: advertise; 
I (3061) NimBLE: disc_mode=2
I (3065) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (3075) NimBLE: 

I (3078) chip[DL]: CHIPoBLE advertising started
E (3083) chip[DL]: Long dispatch time: 742 ms, for event type 2
I (3090) chip[DL]: Starting ESP WiFi layer
D (3095) wifi:filter: set rx policy=0
I (3098) wifi:mode : sta (34:b4:72:74:64:d0)
I (3102) wifi:enable tsf
D (3104) wifi:filter: set rx policy=1
D (3107) wifi:connect status 0 -> 0
D (3111) event: running post WIFI_EVENT:2 with handler 0x42099926 and context 0x3fcad4a0 on loop 0x3fcac304
D (3120) wifi_init_default: wifi_start esp-netif:0x3fcad5f4 event-id2
W (3127) wifi:Haven't to connect to a suitable AP now!
I (3132) chip[DL]: Done driving station state, nothing else to do...
I (3139) phy: chan:1,max_power:80
I (3143) phy: chan:2,max_power:80
I (3147) phy: chan:3,max_power:80
I (3151) phy: chan:4,max_power:80
I (3155) phy: chan:5,max_power:80
I (3159) phy: chan:6,max_power:80
I (3163) phy: chan:7,max_power:80
I (3167) phy: chan:8,max_power:80
I (3171) phy: chan:9,max_power:80
I (3175) phy: chan:10,max_power:80
I (3179) phy: chan:11,max_power:80
D (3133) wifi_init_default: WIFI mac address: 34 b4 72 74 64 d0
I (3184) phy: chan:12,max_power:80
I (3193) phy: chan:13,max_power:80
I (3197) phy: chan:14,max_power:80
W (3201) wifi:Haven't to connect to a suitable AP now!
D (3190) esp_netif_handlers: esp_netif action has started with netif0x3fcad5f4 from event_id=2
D (3215) esp_netif_lwip: check: remote, if=0x3fcad5f4 fn=0x42096f0a

I (3206) chip[DL]: Done driving station state, nothing else to do...
I (3228) phy: chan:1,max_power:80
I (3232) phy: chan:2,max_power:80
I (3236) phy: chan:3,max_power:80
I (3240) phy: chan:4,max_power:80
I (3244) phy: chan:5,max_power:80
I (3248) phy: chan:6,max_power:80
I (3252) phy: chan:7,max_power:80
I (3256) phy: chan:8,max_power:80
I (3260) phy: chan:9,max_power:80
I (3264) phy: chan:10,max_power:80
I (3268) phy: chan:11,max_power:80
I (3272) phy: chan:12,max_power:80
I (3276) phy: chan:13,max_power:80
I (3280) phy: chan:14,max_power:80
I (3285) chip[SVR]: Server initializing...
D (3289) chip[FP]: Initializing FabricTable from persistent storage
D (3296) nvs: nvs_open_from_partition CHIP_KVS 0
I (3300) chip[TS]: Last Known Good Time: [unknown]
I (3306) chip[TS]: Setting Last Known Good Time to firmware build time 2023-03-02T15:02:41
D (3315) nvs: nvs_open_from_partition CHIP_KVS 1
D (3320) nvs: nvs_set_blob g/lkgt 8
D (3324) nvs: nvs_close 47
D (3326) nvs: nvs_open_from_partition CHIP_KVS 0
D (3330) nvs: nvs_get_str_or_blob g/fidx
D (3334) nvs: nvs_close 48
D (3337) nvs: nvs_open_from_partition CHIP_KVS 0
D (3342) nvs: nvs_get_str_or_blob g/fs/c
D (3346) nvs: nvs_close 49
I (3349) chip[DMG]: AccessControl: initializing
I (3354) chip[DMG]: Examples::AccessControlDelegate::Init
I (3360) chip[DMG]: AccessControl: setting
I (3365) chip[DMG]: DefaultAclStorage: initializing
I (3370) chip[DMG]: DefaultAclStorage: 0 entries loaded
D (3376) chip[IN]: UDP::Init bind&listen port=5540
D (3381) chip[IN]: UDP::Init bound to port=5540
D (3386) chip[IN]: UDP::Init bind&listen port=5540
D (3390) chip[IN]: UDP::Init bound to port=5540
D (3395) chip[IN]: BLEBase::Init - setting/overriding transport
D (3401) chip[IN]: TransportMgr initialized
D (3406) nvs: nvs_open_from_partition CHIP_KVS 0
D (3410) nvs: nvs_get_str_or_blob g/gcc
D (3414) nvs: nvs_close 50
D (3417) nvs: nvs_open_from_partition CHIP_KVS 0
D (3421) nvs: nvs_get_str_or_blob g/gdc
D (3425) nvs: nvs_close 51
D (3428) nvs: nvs_open_from_partition CHIP_KVS 1
D (3433) nvs: nvs_set_blob g/gcc 4
D (3437) nvs: nvs_close 52
D (3439) nvs: nvs_open_from_partition CHIP_KVS 1
D (3444) nvs: nvs_set_blob g/gdc 4
D (3448) nvs: nvs_close 53
D (3451) nvs: nvs_open_from_partition CHIP_KVS 0
D (3455) nvs: nvs_get_str_or_blob g/im/ec
D (3459) nvs: nvs_close 54
D (3461) nvs: nvs_open_from_partition CHIP_KVS 1
D (3466) nvs: nvs_set_blob g/im/ec 8
D (3471) nvs: nvs_close 55
I (3473) chip[ZCL]: Using ZAP configuration...
I (3478) esp_matter_cluster: Cluster plugin init common callback
I (3484) chip[DMG]: AccessControlCluster: initializing
I (3490) chip[ZCL]: 0x3c10cf88ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
D (3499) chip[ZCL]: GeneralDiagnostics: OnDeviceReboot
I (3504) chip[ZCL]: Initiating Admin Commissioning cluster.
E (3510) chip[ZCL]: Duplicate attribute override registration failed
D (3518) nvs: nvs_open_from_partition chip-factory 0
D (3522) nvs: nvs_get iteration-count 4
D (3526) nvs: nvs_close 56
D (3529) nvs: nvs_open_from_partition chip-factory 0
D (3534) nvs: nvs_get_str_or_blob salt
D (3537) nvs: nvs_close 57
D (3540) nvs: nvs_open_from_partition chip-factory 0
D (3545) nvs: nvs_get_str_or_blob verifier
D (3549) nvs: nvs_close 58
D (3553) chip[IN]: SecureSession[0x3fc97438]: Allocated Type:1 LSID:40349
D (3559) chip[SC]: Assigned local session key ID 40349
D (3564) chip[SC]: Waiting for PBKDF param request
I (3569) chip[DIS]: Updating services using commissioning mode 1
I (3576) chip[DIS]: CHIP minimal mDNS started advertising.
D (3582) chip[DL]: Using wifi MAC for hostname
D (3587) nvs: nvs_open_from_partition chip-factory 0
D (3592) nvs: nvs_get discriminator 4
D (3595) nvs: nvs_close 59
I (3598) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
D (3609) chip[DIS]: Responding with _matterc._udp.local
D (3614) chip[DIS]: Responding with D7878AEF4976BD67._matterc._udp.local
D (3621) chip[DIS]: Responding with 34B4727464D0.local
D (3626) chip[DIS]: Responding with 34B4727464D0.local
D (3631) chip[DIS]: Responding with _V65521._sub._matterc._udp.local
D (3638) chip[DIS]: Responding with _S15._sub._matterc._udp.local
D (3644) chip[DIS]: Responding with _L3840._sub._matterc._udp.local
D (3650) chip[DIS]: Responding with _CM._sub._matterc._udp.local
D (3656) chip[DIS]: Responding with D7878AEF4976BD67._matterc._udp.local
I (3663) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: D7878AEF4976BD67.
I (3674) chip[DIS]: mDNS service published: _matterc._udp
I (3680) chip[IN]: CASE Server enabling CASE session setups
D (3687) chip[IN]: SecureSession[0x3fc974f0]: Allocated Type:2 LSID:40350
D (3693) chip[SC]: Allocated SecureSession (0x3fc974f0) - waiting for Sigma1 msg
I (3701) chip[SVR]: Joining Multicast groups
D (3706) chip[ZCL]: Emitting StartUp event
I (3710) chip[SVR]: Server Listening...
D (3715) chip[DMG]: Endpoint 0, Cluster 0x0000_001D update version to 2db0e993
I (3721) esp_matter_core: Dynamic endpoint 0 added
I (3728) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0003's Attribute 0x0001 is 0 **********
D (3738) chip[DMG]: Endpoint 1, Cluster 0x0000_0003 update version to e935f1db
I (3745) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0x0000 is 128 **********
D (3756) chip[DMG]: Endpoint 1, Cluster 0x0000_0004 update version to 558823d7
I (3763) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0xFFFC is <invalid type: 0> **********
D (3775) chip[ZCL]: ERR: writing group feature map 1
I (3780) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0005's Attribute 0x0000 is 0 **********
D (3791) chip[DMG]: Endpoint 1, Cluster 0x0000_0005 update version to 249feacf
I (3798) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0xFFFC is 1 **********
I (3808) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x4003 is null **********
I (3819) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x0000 is 1 **********
I (3830) chip[ZCL]: On/Off set value: 1 1
I (3834) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x0000 is 1 **********
I (3845) chip[ZCL]: On/off already set to new value
I (3851) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0002 is 1 **********
I (3861) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0003 is 254 **********
I (3872) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0xFFFC is 3 **********
I (3883) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0000 is 64 **********
I (3893) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x4000 is 64 **********
I (3904) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0000 is 64 **********
I (3915) led_driver_ws2812: led set r:0, g:0, b:0
D (3920) nvs: nvs_open_from_partition endpoint_1 1
D (3925) esp_matter_core: strore attribute in nvs: endpoint_id-0x1, cluster_id-0x8, attribute_id-0x0
D (3934) nvs: nvs_set_blob 8:0 24
D (3938) nvs: nvs_close 60
D (3940) chip[DMG]: Endpoint 1, Cluster 0x0000_0008 update version to 24b0564c
I (3948) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x4010 is null **********
D (3959) chip[DMG]: Endpoint 0, Cluster 0x0000_001D update version to 2db0e994
I (3966) esp_matter_core: Dynamic endpoint 1 added
D (3971) chip[ZCL]: Emitting StartUp event
D (3976) chip[EVL]: LogEvent event number: 0x0000000000000000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000F8D
D (3990) chip[ZCL]: GeneralDiagnostics: OnDeviceReboot
D (3995) chip[DMG]: Endpoint 0, Cluster 0x0000_0033 update version to ec333799
D (4003) chip[EVL]: LogEvent event number: 0x0000000000000001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000FA8
D (4017) nvs: nvs_open_from_partition CHIP_KVS 0
D (4022) nvs: nvs_get_str_or_blob wifi-pass
D (4026) nvs: nvs_close 61
D (4029) nvs: nvs_open_from_partition CHIP_KVS 0
D (4034) nvs: nvs_get_str_or_blob wifi-ssid
D (4038) nvs: nvs_close 62
E (4041) chip[DL]: Long dispatch time: 756 ms, for event type 2
D (4047) nvs: nvs_open_from_partition chip-factory 0
D (4052) nvs: nvs_get discriminator 4
D (4056) nvs: nvs_close 63
D (4059) nvs: nvs_open_from_partition chip-factory 0
D (4064) nvs: nvs_get discriminator 4
D (4068) nvs: nvs_close 64
D (4071) CHIP[DL]: NimBLE start advertising...
I (4075) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (4083) chip[DL]: Device already advertising, stop active advertisement and restart
I (4091) NimBLE: GAP procedure initiated: stop advertising.

D (4098) esp_netif_lwip: esp_netif_start_api 0x3fcad5f4
I (4099) NimBLE: GAP procedure initiated: advertise; 
I (4109) NimBLE: disc_mode=2
I (4112) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (4123) NimBLE: 

I (4126) app_main: Commissioning window opened
D (4130) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3fcad5f4
D (4137) esp_netif_lwip: check: local, if=0x3fcad5f4 fn=0x42097aa0

D (4143) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcad5f4
D (4150) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (4156) event: running post WIFI_EVENT:2 with handler 0x420614ce and context 0x3fcad7f4 on loop 0x3fcac304
D (4166) nvs: nvs_open_from_partition node 0
E (4170) esp_matter_core: Failed to open the node nvs_namespace
D (4176) nvs: nvs_open_from_partition node 1
D (4181) nvs: nvs_set min_uu_ep_id 2 2
D (4185) nvs: nvs_close 65
I (4187) led_driver_ws2812: led set r:0, g:0, b:0
I (4167) chip[DL]: WIFI_EVENT_STA_START
I (4197) phy: chan:1,max_power:80
I (4201) phy: chan:2,max_power:80
I (4205) phy: chan:3,max_power:80
I (4209) phy: chan:4,max_power:80
I (4213) phy: chan:5,max_power:80
I (4217) phy: chan:6,max_power:80
I (4221) phy: chan:7,max_power:80
I (4225) phy: chan:8,max_power:80
I (4229) phy: chan:9,max_power:80
I (4233) phy: chan:10,max_power:80
I (4237) phy: chan:11,max_power:80
I (4241) phy: chan:12,max_power:80
I (4245) phy: chan:13,max_power:80
I (4249) phy: chan:14,max_power:80
W (4254) wifi:Haven't to connect to a suitable AP now!
I (4193) led_driver_ws2812: led set r:0, g:0, b:0
I (4259) chip[DL]: Done driving station state, nothing else to do...
E (4271) chip[DL]: Long dispatch time: 105 ms, for event type 49152
I (4265) led_driver_ws2812: led set r:63, g:51, b:40
D (33570) nvs: nvs_open_from_partition chip-factory 0
D (33570) nvs: nvs_get discriminator 4
D (33570) nvs: nvs_close 66
D (33571) nvs: nvs_open_from_partition chip-factory 0
D (33576) nvs: nvs_get discriminator 4
D (33580) nvs: nvs_close 67
D (33583) CHIP[DL]: NimBLE start advertising...
I (33587) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)
I (33595) chip[DL]: Device already advertising, stop active advertisement and restart
I (33604) NimBLE: GAP procedure initiated: stop advertising.

I (33611) NimBLE: GAP procedure initiated: advertise; 
I (33616) NimBLE: disc_mode=2
I (33620) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (33630) NimBLE: 

I (100348) chip[DL]: BLE GAP connection established (con 1)
I (100349) chip[DL]: CHIPoBLE advertising stopped
D (101237) CHIP[DL]: BLE_GAP_EVENT_MTU = 131 channel id = 4
I (101260) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (101261) chip[BLE]: local and remote recv window sizes = 5
I (101263) chip[BLE]: selected BTP version 4
I (101268) chip[BLE]: using BTP fragment sizes rx 128 / tx 128.
I (101275) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 1
I (101286) chip[DL]: CHIPoBLE subscribe received
D (101291) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 6)
I (101299) NimBLE: GATT procedure initiated: indicate; 
I (101305) NimBLE: att_handle=14

D (101309) chip[IN]: BLE EndPoint 0x3fc9dc90 Connection Complete
I (101358) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (101360) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (101366) chip[EM]: >>> [E:2189r M:138428001] (U) Msg RX from 0:C6C67413691A8884 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D (101379) chip[EM]: Handling via exchange: 2189r, Delegate: 0x3fc994c4
D (101385) chip[SC]: Received PBKDF param request
D (101390) chip[SC]: Peer assigned session ID 11281
D (101395) chip[SC]: Found MRP parameters in the message
I (101402) chip[EM]: <<< [E:2189r M:18525358] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I (101413) chip[IN]: (U) Sending msg 18525358 to IP address 'BLE'
D (101420) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (101428) NimBLE: GATT procedure initiated: indicate; 
I (101434) NimBLE: att_handle=14

D (101439) chip[SC]: Sent PBKDF param response
I (101492) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (101493) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 3)
I (101499) NimBLE: GATT procedure initiated: indicate; 
I (101505) NimBLE: att_handle=14

I (101582) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (101583) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (101591) chip[EM]: >>> [E:2189r M:138428002] (U) Msg RX from 0:C6C67413691A8884 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D (101602) chip[EM]: Found matching exchange: 2189r, Delegate: 0x3fc994c4
D (101609) chip[SC]: Received spake2p msg1
I (102446) chip[EM]: <<< [E:2189r M:18525359] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I (102448) chip[IN]: (U) Sending msg 18525359 to IP address 'BLE'
D (102455) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (102463) NimBLE: GATT procedure initiated: indicate; 
I (102468) NimBLE: att_handle=14

D (102474) chip[SC]: Sent spake2p msg2
E (102477) chip[DL]: Long dispatch time: 886 ms, for event type 7
I (102527) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (102528) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 6)
I (102534) NimBLE: GATT procedure initiated: indicate; 
I (102540) NimBLE: att_handle=14

I (102617) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (102618) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (102626) chip[EM]: >>> [E:2189r M:138428003] (U) Msg RX from 0:C6C67413691A8884 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D (102637) chip[EM]: Found matching exchange: 2189r, Delegate: 0x3fc994c4
D (102644) chip[SC]: Received spake2p msg3
D (102649) chip[SC]: Sending status report. Protocol code 0, exchange 2189
I (102656) chip[EM]: <<< [E:2189r M:18525360] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (102668) chip[IN]: (U) Sending msg 18525360 to IP address 'BLE'
D (102674) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 35)
I (102682) NimBLE: GATT procedure initiated: indicate; 
I (102688) NimBLE: att_handle=14

I (102694) chip[SC]: SecureSession[0x3fc97438]: Moving from state 'kEstablishing' --> 'kActive'
D (102702) chip[IN]: SecureSession[0x3fc97438]: Activated - Type:1 LSID:40349
D (102709) chip[IN]: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:40349 PSID:11281!
I (102719) chip[SVR]: Commissioning completed session establishment step
I (102726) chip[DIS]: Updating services using commissioning mode 0
I (102733) chip[DIS]: CHIP minimal mDNS started advertising.
I (102739) chip[SVR]: Device completed Rendezvous process
E (102746) chip[DL]: Long dispatch time: 120 ms, for event type 7
I (102752) app_main: Commissioning session started
I (102757) app_main: Commissioning window closed
I (102752) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (102797) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (102800) chip[EM]: >>> [E:2190r M:41469037] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (102807) chip[EM]: Handling via exchange: 2190r, Delegate: 0x3fc94b7c
D (102813) chip[IM]: Received Read request
D (102818) chip[DMG]: IM RH moving to [GeneratingReports]
D (102824) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (102833) chip[DMG]: <RE:Run> Cluster 28, Attribute 2 is dirty
D (102839) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D (102849) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (102856) chip[EM]: <<< [E:2190r M:35018060] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (102866) chip[IN]: (S) Sending msg 35018060 on secure session with LSID: 40349
D (102874) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 72)
I (102882) NimBLE: GATT procedure initiated: indicate; 
I (102888) NimBLE: att_handle=14

D (102893) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (102898) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (102906) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (102912) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (103022) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (103023) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (103032) chip[EM]: >>> [E:2191r M:41469038] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (103041) chip[EM]: Handling via exchange: 2191r, Delegate: 0x3fc94b7c
D (103048) chip[IM]: Received Read request
D (103053) chip[DMG]: IM RH moving to [GeneratingReports]
D (103058) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (103067) chip[DMG]: <RE:Run> Cluster 28, Attribute 4 is dirty
D (103073) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D (103083) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (103090) chip[EM]: <<< [E:2191r M:35018061] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (103101) chip[IN]: (S) Sending msg 35018061 on secure session with LSID: 40349
D (103109) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 72)
I (103117) NimBLE: GATT procedure initiated: indicate; 
I (103122) NimBLE: att_handle=14

D (103128) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (103132) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (103140) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (103146) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (103202) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (103247) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (103250) chip[EM]: >>> [E:2192r M:41469039] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (103257) chip[EM]: Handling via exchange: 2192r, Delegate: 0x3fc94b7c
D (103263) chip[IM]: Received Read request
D (103268) chip[DMG]: IM RH moving to [GeneratingReports]
D (103274) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (103283) chip[DMG]: <RE:Run> Cluster 3e, Attribute 2 is dirty
D (103289) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D (103299) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (103306) chip[EM]: <<< [E:2192r M:35018062] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (103316) chip[IN]: (S) Sending msg 35018062 on secure session with LSID: 40349
D (103324) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 71)
I (103332) NimBLE: GATT procedure initiated: indicate; 
I (103338) NimBLE: att_handle=14

D (103343) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (103348) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (103356) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (103362) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (103427) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (103428) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (103437) chip[EM]: >>> [E:2193r M:41469040] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (103446) chip[EM]: Handling via exchange: 2193r, Delegate: 0x3fc94b7c
D (103453) chip[IM]: Received Read request
D (103458) chip[DMG]: IM RH moving to [GeneratingReports]
D (103463) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (103472) chip[DMG]: <RE:Run> Cluster 3e, Attribute 3 is dirty
D (103478) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D (103488) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (103495) chip[EM]: <<< [E:2193r M:35018063] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (103506) chip[IN]: (S) Sending msg 35018063 on secure session with LSID: 40349
D (103514) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 71)
I (103522) NimBLE: GATT procedure initiated: indicate; 
I (103527) NimBLE: att_handle=14

D (103533) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (103537) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (103545) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (103551) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (103652) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (103653) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (103662) chip[EM]: >>> [E:2194r M:41469041] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (103671) chip[EM]: Handling via exchange: 2194r, Delegate: 0x3fc94b7c
D (103678) chip[IM]: Received Read request
D (103683) chip[DMG]: IM RH moving to [GeneratingReports]
D (103688) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (103697) chip[DMG]: <RE:Run> Cluster 3e, Attribute 1 is dirty
D (103703) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D (103713) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (103720) chip[EM]: <<< [E:2194r M:35018064] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (103731) chip[IN]: (S) Sending msg 35018064 on secure session with LSID: 40349
D (103739) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 71)
I (103747) NimBLE: GATT procedure initiated: indicate; 
I (103752) NimBLE: att_handle=14

D (103758) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (103762) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (103770) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (103776) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (103832) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (103877) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (103880) chip[EM]: >>> [E:2195r M:41469042] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (103887) chip[EM]: Handling via exchange: 2195r, Delegate: 0x3fc94b7c
D (103893) chip[IM]: Received Read request
D (103898) chip[DMG]: IM RH moving to [GeneratingReports]
D (103904) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (103913) chip[DMG]: <RE:Run> Cluster 1d, Attribute 1 is dirty
D (103919) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D (103929) chip[DMG]: <RE> Sending report (payload has 316 bytes)...
I (103937) chip[EM]: <<< [E:2195r M:35018065] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (103946) chip[IN]: (S) Sending msg 35018065 on secure session with LSID: 40349
D (103954) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (103962) NimBLE: GATT procedure initiated: indicate; 
I (103968) NimBLE: att_handle=14

D (103973) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (103978) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (103986) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (103992) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (104057) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (104058) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (104064) NimBLE: GATT procedure initiated: indicate; 
I (104070) NimBLE: att_handle=14

I (104147) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (104148) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 99)
I (104154) NimBLE: GATT procedure initiated: indicate; 
I (104160) NimBLE: att_handle=14

I (104237) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (104238) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (104247) chip[EM]: >>> [E:2196r M:41469043] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (104256) chip[EM]: Handling via exchange: 2196r, Delegate: 0x3fc94b7c
D (104263) chip[IM]: Received Read request
D (104268) chip[DMG]: IM RH moving to [GeneratingReports]
D (104273) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (104282) chip[DMG]: <RE:Run> Cluster 31, Attribute fffc is dirty
D (104288) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D (104299) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (104306) chip[EM]: <<< [E:2196r M:35018066] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (104316) chip[IN]: (S) Sending msg 35018066 on secure session with LSID: 40349
D (104324) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 72)
I (104332) NimBLE: GATT procedure initiated: indicate; 
I (104338) NimBLE: att_handle=14

D (104343) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (104347) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (104356) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (104361) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (104417) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (105452) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (105455) chip[EM]: >>> [E:2197r M:41469044] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D (105462) chip[EM]: Handling via exchange: 2197r, Delegate: 0x3fc94b7c
D (105469) chip[DMG]: Got Timed Request with timeout 10000: handler 0x3fc94f98 exchange 2197r
I (105478) chip[EM]: <<< [E:2197r M:35018067] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I (105489) chip[IN]: (S) Sending msg 35018067 on secure session with LSID: 40349
D (105497) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 43)
I (105505) NimBLE: GATT procedure initiated: indicate; 
I (105511) NimBLE: att_handle=14

D (105516) chip[DMG]: Timed Request time limit 0x000000000001C341: handler 0x3fc94f98 exchange 2197r
I (105587) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (105588) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (105597) chip[EM]: >>> [E:2197r M:41469045] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (105607) chip[EM]: Found matching exchange: 2197r, Delegate: 0x3fc94f98
D (105614) chip[DMG]: Timed following action arrived at 0x0000000000019C93: handler 0x3fc94f98 exchange 2197r
D (105624) chip[DMG]: Handing timed invoke to IM engine: handler 0x3fc94f98 exchange 2197r
D (105633) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I (105641) esp_matter_command: Received command 0x0000 for enpoint 0x0000's cluster 0x00000030
I (105650) chip[FS]: GeneralCommissioning: Received ArmFailSafe (120s)
I (105657) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 1 **********
D (105668) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 1b51172e
D (105676) chip[DMG]: Command handler moving to [ Preparing]
D (105681) chip[DMG]: Command handler moving to [AddingComm]
D (105687) chip[DMG]: Command handler moving to [AddedComma]
D (105693) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (105701) chip[EM]: <<< [E:2197r M:35018068] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (105712) chip[IN]: (S) Sending msg 35018068 on secure session with LSID: 40349
D (105720) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 71)
I (105728) NimBLE: GATT procedure initiated: indicate; 
I (105734) NimBLE: att_handle=14

D (105739) chip[DMG]: Command handler moving to [CommandSen]
D (105744) chip[DMG]: Command handler moving to [AwaitingDe]
E (105750) chip[DL]: Long dispatch time: 155 ms, for event type 7
I (105812) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (105813) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (105822) chip[EM]: >>> [E:2198r M:41469046] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (105831) chip[EM]: Handling via exchange: 2198r, Delegate: 0x3fc94b7c
D (105838) chip[IM]: Received Read request
D (105843) chip[DMG]: IM RH moving to [GeneratingReports]
D (105848) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (105857) chip[DMG]: <RE:Run> Cluster 30, Attribute 3 is dirty
D (105863) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D (105873) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (105880) chip[EM]: <<< [E:2198r M:35018069] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (105891) chip[IN]: (S) Sending msg 35018069 on secure session with LSID: 40349
D (105899) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 71)
I (105907) NimBLE: GATT procedure initiated: indicate; 
I (105912) NimBLE: att_handle=14

D (105918) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (105922) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (105930) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (105936) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (105992) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (105993) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (106001) chip[EM]: >>> [E:2199r M:41469047] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D (106011) chip[EM]: Handling via exchange: 2199r, Delegate: 0x3fc94b7c
D (106018) chip[DMG]: Got Timed Request with timeout 10000: handler 0x3fc94f98 exchange 2199r
I (106028) chip[EM]: <<< [E:2199r M:35018070] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I (106038) chip[IN]: (S) Sending msg 35018070 on secure session with LSID: 40349
D (106046) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 43)
I (106054) NimBLE: GATT procedure initiated: indicate; 
I (106060) NimBLE: att_handle=14

D (106065) chip[DMG]: Timed Request time limit 0x000000000001C567: handler 0x3fc94f98 exchange 2199r
I (106172) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (106173) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (106182) chip[EM]: >>> [E:2199r M:41469048] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (106192) chip[EM]: Found matching exchange: 2199r, Delegate: 0x3fc94f98
D (106199) chip[DMG]: Timed following action arrived at 0x0000000000019EDC: handler 0x3fc94f98 exchange 2199r
D (106209) chip[DMG]: Handing timed invoke to IM engine: handler 0x3fc94f98 exchange 2199r
D (106218) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
I (106226) esp_matter_command: Received command 0x0002 for enpoint 0x0000's cluster 0x00000030
D (106235) nvs: nvs_open_from_partition chip-config 1
D (106240) nvs: nvs_set reg-location 4 0
I (106244) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
D (106251) nvs: nvs_close 68
D (106254) nvs: nvs_open_from_partition chip-config 1
D (106259) nvs: nvs_set_str country-code IN
I (106263) chip[DL]: NVS set: chip-config/country-code = "IN"
D (106269) nvs: nvs_close 69
I (106272) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 1 **********
D (106283) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 1b51172f
D (106291) chip[DMG]: Command handler moving to [ Preparing]
D (106296) chip[DMG]: Command handler moving to [AddingComm]
D (106302) chip[DMG]: Command handler moving to [AddedComma]
D (106308) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (106316) chip[EM]: <<< [E:2199r M:35018071] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (106328) chip[IN]: (S) Sending msg 35018071 on secure session with LSID: 40349
D (106336) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 71)
I (106344) NimBLE: GATT procedure initiated: indicate; 
I (106349) NimBLE: att_handle=14

D (106355) chip[DMG]: Command handler moving to [CommandSen]
D (106359) chip[DMG]: Command handler moving to [AwaitingDe]
E (106365) chip[DL]: Long dispatch time: 185 ms, for event type 7
I (106442) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (106443) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (106452) chip[EM]: >>> [E:2200r M:41469049] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (106462) chip[EM]: Handling via exchange: 2200r, Delegate: 0x3fc94b7c
D (106469) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I (106477) esp_matter_command: Received command 0x0002 for enpoint 0x0000's cluster 0x0000003E
I (106487) chip[ZCL]: OpCreds: Certificate Chain request received for DAC
D (106494) chip[DMG]: Command handler moving to [ Preparing]
D (106500) chip[DMG]: Command handler moving to [AddingComm]
D (106505) chip[DMG]: Command handler moving to [AddedComma]
D (106511) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (106521) chip[EM]: <<< [E:2200r M:35018072] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (106531) chip[IN]: (S) Sending msg 35018072 on secure session with LSID: 40349
D (106539) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (106547) NimBLE: GATT procedure initiated: indicate; 
I (106553) NimBLE: att_handle=14

D (106558) chip[DMG]: Command handler moving to [CommandSen]
D (106563) chip[DMG]: Command handler moving to [AwaitingDe]
E (106569) chip[DL]: Long dispatch time: 118 ms, for event type 7
I (106622) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (106623) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (106629) NimBLE: GATT procedure initiated: indicate; 
I (106635) NimBLE: att_handle=14

I (106712) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (106713) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (106719) NimBLE: GATT procedure initiated: indicate; 
I (106725) NimBLE: att_handle=14

I (106802) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (106803) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (106809) NimBLE: GATT procedure initiated: indicate; 
I (106815) NimBLE: att_handle=14

I (106892) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (106893) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
D (106900) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 58)
I (106908) NimBLE: GATT procedure initiated: indicate; 
I (106913) NimBLE: att_handle=14

I (106982) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (106983) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (106992) chip[EM]: >>> [E:2201r M:41469050] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (107002) chip[EM]: Handling via exchange: 2201r, Delegate: 0x3fc94b7c
D (107009) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I (107017) esp_matter_command: Received command 0x0002 for enpoint 0x0000's cluster 0x0000003E
I (107027) chip[ZCL]: OpCreds: Certificate Chain request received for PAI
D (107034) chip[DMG]: Command handler moving to [ Preparing]
D (107040) chip[DMG]: Command handler moving to [AddingComm]
D (107045) chip[DMG]: Command handler moving to [AddedComma]
D (107051) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (107061) chip[EM]: <<< [E:2201r M:35018073] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (107071) chip[IN]: (S) Sending msg 35018073 on secure session with LSID: 40349
D (107079) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (107087) NimBLE: GATT procedure initiated: indicate; 
I (107093) NimBLE: att_handle=14

D (107098) chip[DMG]: Command handler moving to [CommandSen]
D (107103) chip[DMG]: Command handler moving to [AwaitingDe]
E (107109) chip[DL]: Long dispatch time: 118 ms, for event type 7
I (107162) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (107163) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (107169) NimBLE: GATT procedure initiated: indicate; 
I (107175) NimBLE: att_handle=14

I (107252) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (107253) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (107259) NimBLE: GATT procedure initiated: indicate; 
I (107265) NimBLE: att_handle=14

I (107342) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (107343) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (107349) NimBLE: GATT procedure initiated: indicate; 
I (107355) NimBLE: att_handle=14

I (107432) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (107433) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
D (107440) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 28)
I (107448) NimBLE: GATT procedure initiated: indicate; 
I (107453) NimBLE: att_handle=14

I (107522) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (107523) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (107532) chip[EM]: >>> [E:2202r M:41469051] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (107542) chip[EM]: Handling via exchange: 2202r, Delegate: 0x3fc94b7c
D (107549) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I (107557) esp_matter_command: Received command 0x0000 for enpoint 0x0000's cluster 0x0000003E
I (107567) chip[ZCL]: OpCreds: Received an AttestationRequest command
I (107743) chip[ZCL]: OpCreds: AttestationRequest successful.
D (107744) chip[DMG]: Command handler moving to [ Preparing]
D (107744) chip[DMG]: Command handler moving to [AddingComm]
D (107750) chip[DMG]: Command handler moving to [AddedComma]
D (107756) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (107767) chip[EM]: <<< [E:2202r M:35018074] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (107776) chip[IN]: (S) Sending msg 35018074 on secure session with LSID: 40349
D (107784) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (107792) NimBLE: GATT procedure initiated: indicate; 
I (107798) NimBLE: att_handle=14

D (107803) chip[DMG]: Command handler moving to [CommandSen]
D (107808) chip[DMG]: Command handler moving to [AwaitingDe]
E (107814) chip[DL]: Long dispatch time: 283 ms, for event type 7
I (107882) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (107883) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (107889) NimBLE: GATT procedure initiated: indicate; 
I (107895) NimBLE: att_handle=14

I (107972) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (107973) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (107979) NimBLE: GATT procedure initiated: indicate; 
I (107985) NimBLE: att_handle=14

I (108062) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (108063) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (108069) NimBLE: GATT procedure initiated: indicate; 
I (108075) NimBLE: att_handle=14

I (108152) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (108153) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
D (108160) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (108168) NimBLE: GATT procedure initiated: indicate; 
I (108173) NimBLE: att_handle=14

I (108242) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (108243) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 90)
I (108249) NimBLE: GATT procedure initiated: indicate; 
I (108255) NimBLE: att_handle=14

I (108377) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (108378) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
I (108387) chip[EM]: >>> [E:2203r M:41469052] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (108397) chip[EM]: Handling via exchange: 2203r, Delegate: 0x3fc94b7c
D (108404) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I (108412) esp_matter_command: Received command 0x0004 for enpoint 0x0000's cluster 0x0000003E
I (108422) chip[ZCL]: OpCreds: Received a CSRRequest command
D (108428) chip[ZCL]: OpCreds: Finding fabric with fabricIndex 0x0
I (108766) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded
I (108935) chip[ZCL]: OpCreds: CSRRequest successful.
D (108935) chip[DMG]: Command handler moving to [ Preparing]
D (108936) chip[DMG]: Command handler moving to [AddingComm]
D (108941) chip[DMG]: Command handler moving to [AddedComma]
D (108947) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (108956) chip[EM]: <<< [E:2203r M:35018075] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (108967) chip[IN]: (S) Sending msg 35018075 on secure session with LSID: 40349
D (108975) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (108983) NimBLE: GATT procedure initiated: indicate; 
I (108989) NimBLE: att_handle=14

D (108994) chip[DMG]: Command handler moving to [CommandSen]
D (108999) chip[DMG]: Command handler moving to [AwaitingDe]
E (109005) chip[DL]: Long dispatch time: 619 ms, for event type 7
I (109052) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (109053) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (109059) NimBLE: GATT procedure initiated: indicate; 
I (109065) NimBLE: att_handle=14

I (109142) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
D (109143) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 1, len 128)
I (109149) NimBLE: GATT procedure initiated: indicate; 
I (109155) NimBLE: att_handle=14

I (109232) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (110852) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0
I (110853) chip[DL]: CHIPoBLE unsubscribe received
I (110858) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213)
D (110865) chip[IN]: Clearing BLE pending packets.
I (110870) chip[BLE]: Releasing end point's BLE connection back to application.
ESP-ROM:ESP-`

@KhushbuShah25
Copy link

Error : "Device did not pass attestation"

Android side Logs :

03-03 13:13:35.369 D/DIS (14028): Checking node lookup status after 15046 ms 03-03 13:13:35.369 E/DIS (14028): OperationalSessionSetup[1:6FCD0EB75A99C7FF]: operational discovery failed: third_party/connectedhomeip/next/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout 03-03 13:13:35.370 W/ChipController(14028): Failed to resolve pointer for device 6FCD0EB75A99C7FF [CONTEXT service_id=336 ] 03-03 13:13:35.370 W/ChipController(14028): chip.devicecontroller.ChipDeviceControllerException: third_party/connectedhomeip/next/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout 03-03 13:13:35.372 I/MatterCommissioner(14028): Could not disarm failsafe (error=0xBA5C1960) [CONTEXT service_id=336 ] 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): Commissioning failed with state Attestation failure. [CONTEXT service_id=336 ] 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): m.elb: Device did not pass attestation (error(s)=[3]) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at m.eme.g(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:36) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at m.ely.b(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:0) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at m.ngq.f(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:4) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at m.nno.run(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:8) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at android.os.Handler.handleCallback(Handler.java:938) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at android.os.Handler.dispatchMessage(Handler.java:99) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at android.os.Looper.loop(Looper.java:233) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at android.app.ActivityThread.main(ActivityThread.java:8010) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at java.lang.reflect.Method.invoke(Native Method) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:631) 03-03 13:13:35.373 E/SetupDeviceViewModel(14028): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:978) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): Showing error status. [CONTEXT service_id=336 ] 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): m.fjn: Device did not pass attestation (error(s)=[3]) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.fqu.a(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:12) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.nue.a(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:0) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.nud.a(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:7) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.ecs.b(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:87) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.ngq.f(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:4) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.nno.run(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:7) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at android.os.Handler.handleCallback(Handler.java:938) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at android.os.Handler.dispatchMessage(Handler.java:99) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at android.os.Looper.loop(Looper.java:233) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at android.app.ActivityThread.main(ActivityThread.java:8010) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at java.lang.reflect.Method.invoke(Native Method) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:631) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:978) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): Caused by: m.elb: Device did not pass attestation (error(s)=[3]) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.eme.g(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:36) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.ely.b(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:0) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.ngq.f(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:4) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): at m.nno.run(:com.google.android.gms.policy_home@225010900@225010900065.494655337.494655337:8) 03-03 13:13:35.374 E/SetupDeviceChimeraActiv(14028): ... 7 more

@pierredelisle
Copy link
Contributor

@edWin-m
I looked at the phone logs you provided.

03-03 09:15:32.598 24520 29767 I ManagedMdnsServiceBrows: Stopping mDNS search for E643C47590770ABC-0A9AE7A233A0999B [CONTEXT service_id=336 ]
03-03 09:15:32.603 24520 24975 I ServiceResolverAdapter: Timed out searching for E643C47590770ABC-0A9AE7A233A0999B._matter._tcp [CONTEXT service_id=336 ]
...
03-03 09:15:42.609 24520 29733 E DIS     : OperationalSessionSetup[1:0A9AE7A233A0999B]: operational discovery failed: third_party/connectedhomeip/current/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
03-03 09:15:42.612 24520 29733 W ChipController: Failed to resolve pointer for device A9AE7A233A0999B [CONTEXT service_id=336 ]
03-03 09:15:42.612 24520 29733 W ChipController: chip.devicecontroller.ChipDeviceControllerException: third_party/connectedhomeip/current/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
03-03 09:15:42.614 24520 24520 I MatterCommissioner: Could not disarm failsafe (error=0x32) [CONTEXT service_id=336 ]
03-03 09:15:42.615 24520 24520 E SetupDeviceViewModel: Commissioning failed with state Attestation failure. [CONTEXT service_id=336 ]
03-03 09:15:42.615 24520 24520 E SetupDeviceViewModel: m.emi: Device did not pass attestation (error(s)=[3])

I've also experienced some mDNS issues yesterday that eventually bubbled up as Device Attestation failures.
But these errors have been intermittent. The team is working on a fix, and until then, if discovery is via BLE and the device is on WiFi, then these issues may occur.

I will be releasing version 1.4.0 shortly, which ignores device attestation failures. However, please note that if you build from main, that fix is already there (see commit 0eb3c6d). There should be no device attestation failures, but intermittent mDNS issues will still arise until a platform fix is done.

@edWin-m
Copy link
Contributor Author

edWin-m commented Mar 4, 2023

@pierredelisle noted. I have already noticed the changes introduced in commit 0eb3c6d. Is there a way we can be notified when the team has found a fix for the mDNS issue?

@KhushbuShah25
Copy link

KhushbuShah25 commented Mar 4, 2023

Hi @pierredelisle ,
Thank you so much for updating about commit and known issue.
I have tried app with the commit 0eb3c6d.
Also tried by setting true value for deviceAttestationFailureIgnored flag at this line, but the app is still showing same error mostly due to mDNS issue.

@tetedoie
Copy link

tetedoie commented Mar 7, 2023

I was also experiencing the same issue constantly yesterday and past Friday. Today, commissioning is working again even before commit 0eb3c6d.

@KhushbuShah25
Copy link

Hi @tetedoie , thanks for updating. it is working now.

@edWin-m
Copy link
Contributor Author

edWin-m commented Mar 8, 2023

@khushbushah2302 Same here. @pierredelisle Does this mean the issue has been fixed?

@pierredelisle
Copy link
Contributor

Well, the root cause of the "device certification failure" has been fixed. So I'll close this issue.

However, there is a known issue with mDNS (as I mentioned above) that may happen (it's not deterministic), and the error message that bubbles up may vary. Team is working on a fix.

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

5 participants