search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.52k stars 2.02k forks source link

M5 lightbulb pairing fails when 11-digit Manual setup code is used to pair #15767

Closed woody-apple closed 2 years ago

woody-apple commented 2 years ago

Problem

Pairing error occurred

Logs:

rst:0xc (SW_CPU_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6628
load:0x40078000,len:14780
load:0x40080400,len:3792
0x40080400: _init at ??:?

entry 0x40080694
I (27) boot: ESP-IDF v4.4-263-g000d3823bb-dirty 2nd stage bootloader
I (27) boot: compile time 12:01:19
I (27) boot: chip revision: 3
I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (39) boot.esp32: SPI Speed      : 40MHz
I (43) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 4MB
I (52) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (76) boot:  1 otadata          OTA data         01 00 0000f000 00002000
I (84) boot:  2 phy_init         RF data          01 01 00011000 00001000
I (91) boot:  3 ota_0            OTA app          00 10 00020000 00177000
I (99) boot:  4 ota_1            OTA app          00 11 001a0000 00177000
I (106) boot:  5 ot_storage       Unknown data     01 3a 00317000 00002000
I (114) boot: End of partition table
I (118) boot_comm: chip revision: 3, min. application chip revision: 0
I (125) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=36fd0h (225232) map
I (215) esp_image: segment 1: paddr=00056ff8 vaddr=3ffbdb60 size=08518h ( 34072) load
I (229) esp_image: segment 2: paddr=0005f518 vaddr=40080000 size=00b00h (  2816) load
I (230) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=f48c8h (1001672) map
I (597) esp_image: segment 4: paddr=001548f0 vaddr=40080b00 size=1d8d8h (121048) load
I (647) esp_image: segment 5: paddr=001721d0 vaddr=50000000 size=00010h (    16) load
I (663) boot: Loaded app from partition at offset 0x20000
I (663) boot: Disabling RNG early entropy source...
I (675) cpu_start: Pro cpu up.
I (675) cpu_start: Starting app cpu, entry point is 0x400814dc
0x400814dc: call_start_cpu1 at /Users/ajaybadagowni/tools/esp-idf/components/esp_system/port/cpu_start.c:160

I (662) cpu_start: App cpu up.
I (691) cpu_start: Pro cpu start user code
I (691) cpu_start: cpu freq: 160000000
I (691) cpu_start: Application information:
I (696) cpu_start: Project name:     chip-all-clusters-app
I (702) cpu_start: App version:      TE8/rc3-140-g448578dd0-dirty
I (709) cpu_start: Compile time:     Mar  1 2022 18:02:47
I (715) cpu_start: ELF file SHA256:  89c08025d8cbfbeb...
I (721) cpu_start: ESP-IDF:          v4.4-263-g000d3823bb-dirty
I (728) heap_init: Initializing. RAM available for dynamic allocation:
I (734) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (741) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (747) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (753) heap_init: At 3FFD6A80 len 00009580 (37 KiB): DRAM
I (759) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (765) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (772) heap_init: At 4009E3D8 len 00001C28 (7 KiB): IRAM
I (779) spi_flash: detected chip: generic
I (783) spi_flash: flash io: dio
W (786) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (803) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (810) all-clusters-app: All Clusters Demo!
I (820) all-clusters-app: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, 
I (820) all-clusters-app: silicon revision 3, 
I (830) all-clusters-app: 4MB external flash

I (1040) wifi:wifi driver task: 3ffdefdc, prio:23, stack:6656, core=0
I (1040) system_api: Base MAC address is not set
I (1040) system_api: read default base MAC address from EFUSE
> I (1070) wifi:wifi firmware version: 7679c42
I (1080) wifi:wifi certification version: v7.0
I (1080) wifi:config NVS flash: enabled
I (1080) wifi:config nano formating: disabled
I (1090) wifi:Init data frame dynamic rx buffer num: 32
I (1090) wifi:Init management frame dynamic rx buffer num: 32
I (1090) wifi:Init management short buffer num: 32
I (1100) wifi:Init dynamic tx buffer num: 32
I (1100) wifi:Init static rx buffer size: 1600
I (1100) wifi:Init static rx buffer num: 10
I (1110) wifi:Init dynamic rx buffer num: 32
I (1120) wifi_init: rx ba win: 6
I (1120) wifi_init: tcpip mbox: 32
I (1130) wifi_init: udp mbox: 6
I (1130) wifi_init: tcp mbox: 6
I (1130) wifi_init: tcp tx win: 5744
I (1140) wifi_init: tcp rx win: 5744
I (1140) wifi_init: tcp mss: 1440
I (1140) wifi_init: WiFi IRAM OP enabled
I (1150) wifi_init: WiFi RX IRAM OP enabled
I (1170) chip[DL]: NVS set: chip-counters/reboot-count = 122 (0x7A)
I (1170) chip[DL]: Changing ESP WiFi mode: AP -> STA+AP
I (1170) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA
I (1180) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (1190) BTDM_INIT: BT controller compile version [30c8196]
I (1200) chip[SVR]: SetupQRCode: [MT:-24J0KQS02.90648G00]
I (1200) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code:
I (1210) chip[SVR]: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J0KQS02.90648G00
I (1220) chip[SVR]: Manual pairing code: [33331712336]
I (1220) chip[SVR]: Long manual pairing code: [733317123365521327692]
I (1200) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1620) CHIP[DL]: BLE host-controller synced
I (2130) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3674)
I (2130) NimBLE: GAP procedure initiated: advertise; 
I (2140) NimBLE: disc_mode=2
I (2140) NimBLE:  adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2150) NimBLE: 

I (2170) chip[DL]: CHIPoBLE advertising started
E (2170) chip[DL]: Long dispatch time: 977 ms, for event type 2
I (2170) chip[DL]: Starting ESP WiFi layer
I (2180) wifi:mode : sta (b8:f0:09:c4:97:38)
I (2180) wifi:enable tsf
W (2190) wifi:Haven't to connect to a suitable AP now!
I (2190) chip[DL]: Done driving station state, nothing else to do...
W (2200) wifi:Haven't to connect to a suitable AP now!
I (2200) chip[DL]: Done driving station state, nothing else to do...
I (2210) chip[ZCL]: Using ZAP configuration...
I (2230) chip[ZCL]: Initiating Admin Commissioning cluster.
I (2230) chip[ZCL]: Door Lock server initialized
I (2240) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
I (2250) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (2260) app-devicecallbacks: Current free heap: 75120

I (2260) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (2270) app-devicecallbacks: Unhandled cluster ID: 4
I (2290) app-devicecallbacks: Current free heap: 75120

E (2290) chip[ZCL]: Trying to write invalid Calendar Type
E (2300) chip[ZCL]: Failed to write calendar type with error: 0x87
I (2300) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2300) all-clusters-app: Display initialized (height 240, width 320)
I (2310) app-devicecallbacks: Current free heap: 77040

I (2320) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (2330) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2350) app-devicecallbacks: Unhandled cluster ID: 4
I (2350) app-devicecallbacks: Current free heap: 74212

I (2360) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2370) app-devicecallbacks: Unhandled cluster ID: 5
I (2380) app-devicecallbacks: Current free heap: 74212

I (2390) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2390) app-devicecallbacks: Current free heap: 74212

I (2400) chip[ZCL]: Window Covering Cluster init
I (2410) chip[ZCL]: Initialize PCC Server Cluster [EP:1]
I (2420) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (2430) app-devicecallbacks: Unhandled cluster ID: 768
I (2430) app-devicecallbacks: Current free heap: 75004

I (2440) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008'
I (2450) app-devicecallbacks: Unhandled cluster ID: 768
I (2460) app-devicecallbacks: Current free heap: 76072

I (2460) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (2470) app-devicecallbacks: Unhandled cluster ID: 768
I (2480) app-devicecallbacks: Current free heap: 76072

I (2480) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2490) app-devicecallbacks: Unhandled cluster ID: 1030
I (2510) app-devicecallbacks: Current free heap: 76072

I (2510) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2520) app-devicecallbacks: Unhandled cluster ID: 1030
I (2530) app-devicecallbacks: Current free heap: 76072

I (2530) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! 
I (2540) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!!
I (2540) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2560) app-devicecallbacks: Unhandled cluster ID: 1280
I (2570) app-devicecallbacks: Current free heap: 76072

I (2570) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2580) app-devicecallbacks: Unhandled cluster ID: 1280
I (2590) app-devicecallbacks: Current free heap: 76072

I (2590) chip[ZCL]: Failed to send IAS Zone update. Err 0x70
I (2610) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (2620) app-devicecallbacks: Unhandled cluster ID: 4
I (2620) app-devicecallbacks: Current free heap: 76072

I (2630) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001'
I (2630) app-devicecallbacks: Unhandled cluster ID: 1030
I (2640) app-devicecallbacks: Current free heap: 76072

I (2650) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002'
I (2660) app-devicecallbacks: Unhandled cluster ID: 1030
I (2670) app-devicecallbacks: Current free heap: 76072

I (2670) chip[DMG]: AccessControl: initializing
I (2680) chip[DMG]: Examples::AccessControlDelegate::Init
I (2680) chip[DMG]: AccessControl: unable to load stored ACL entries; using empty list instead
I (2700) chip[DMG]: AccessControl: setting
I (2710) chip[DL]: NVS set: chip-counters/GlobalMCTR = 321000 (0x4E5E8)
I (2720) chip[DL]: NVS set: chip-counters/global-eidc = 7995392 (0x7A0000)
I (2780) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (2780) chip[DIS]: CHIP minimal mDNS started advertising.
I (2790) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (2800) chip[DIS]: Start dns-sd server - no current nodeId
I (2810) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3674/14
I (2810) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (2820) chip[DIS]: mDNS service published: _matterc._udp
I (2820) chip[IN]: CASE Server enabling CASE session setups
I (2840) chip[SVR]: Joining Multicast groups
I (2840) chip[SVR]: Server Listening...
I (2840) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2850) app-devicecallbacks: Unhandled cluster ID: 1026
I (2870) app-devicecallbacks: Current free heap: 74040

I (2870) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2880) app-devicecallbacks: Unhandled cluster ID: 257
I (2880) app-devicecallbacks: Current free heap: 73920

I (2890) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2910) app-devicecallbacks: Unhandled cluster ID: 1030
I (2910) app-devicecallbacks: Current free heap: 72976

I (2920) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2930) app-devicecallbacks: Unhandled cluster ID: 69
I (2930) app-devicecallbacks: Current free heap: 72856

I (2940) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2950) app-devicecallbacks: Unhandled cluster ID: 1026
I (2960) app-devicecallbacks: Current free heap: 72496

I (2960) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2970) app-devicecallbacks: Unhandled cluster ID: 513
I (2980) app-devicecallbacks: Current free heap: 72496

I (2980) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c'
I (3000) app-devicecallbacks: Unhandled cluster ID: 513
I (3010) app-devicecallbacks: Current free heap: 72448

I (3010) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0011'
I (3020) app-devicecallbacks: Unhandled cluster ID: 513
I (3030) app-devicecallbacks: Current free heap: 72368

I (3030) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0012'
I (3050) app-devicecallbacks: Unhandled cluster ID: 513
I (3050) app-devicecallbacks: Current free heap: 72240

I (3060) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3070) app-devicecallbacks: Unhandled cluster ID: 1029
I (3070) app-devicecallbacks: Current free heap: 72120

I (3080) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3100) app-devicecallbacks: Unhandled cluster ID: 1024
I (3100) app-devicecallbacks: Current free heap: 71964

I (3110) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3120) app-devicecallbacks: Current free heap: 71844

I (3130) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3140) app-devicecallbacks: Current free heap: 71740

I (3150) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3160) app-devicecallbacks: Unhandled cluster ID: 768
I (3160) app-devicecallbacks: Current free heap: 71620

I (3170) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (3190) app-devicecallbacks: Unhandled cluster ID: 768
I (3190) app-devicecallbacks: Current free heap: 71552

E (3200) chip[DL]: Long dispatch time: 986 ms, for event type 2
I (3200) app-devicecallbacks: Current free heap: 71552

I (3210) chip[DL]: WIFI_EVENT_STA_START
W (3210) wifi:Haven't to connect to a suitable AP now!
I (3210) chip[DL]: Done driving station state, nothing else to do...
I (3230) app-devicecallbacks: Current free heap: 71552

I (3230) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3674)
I (3240) chip[DL]: Device already advertising, stop active advertisement and restart
I (3240) NimBLE: GAP procedure initiated: stop advertising.

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

> 
> 
> 
> 
I (32780) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3674)
I (32780) chip[DL]: Device already advertising, stop active advertisement and restart
I (32790) NimBLE: GAP procedure initiated: stop advertising.

I (32800) NimBLE: GAP procedure initiated: advertise; 
I (32810) NimBLE: disc_mode=2
I (32810) NimBLE:  adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (32820) NimBLE: 

I (87340) chip[DL]: BLE GAP connection established (con 0)
I (87340) chip[DL]: CHIPoBLE advertising stopped
I (87340) app-devicecallbacks: Current free heap: 71552

> I (88000) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (88010) chip[BLE]: local and remote recv window sizes = 5
I (88010) chip[BLE]: selected BTP version 4
I (88020) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (88330) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1
I (88340) chip[DL]: CHIPoBLE subscribe received
I (88340) NimBLE: GATT procedure initiated: notify; 
I (88350) NimBLE: att_handle=14

I (88350) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (88360) app-devicecallbacks: CHIPoBLE connection established
I (88360) app-devicecallbacks: Current free heap: 71552

I (88390) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (88400) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:3790202183 on exchange 45550r
I (88410) chip[IN]: Prepared unauthenticated message 0x3ffe7664 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 45550r with MessageCounter:3310657552.
I (88430) chip[IN]: Sending unauthenticated msg 0x3ffe7664 with MessageCounter:3310657552 to 0x0000000000000000 at monotonic time: 87648 msec
I (88440) NimBLE: GATT procedure initiated: notify; 
I (88440) NimBLE: att_handle=14

I (88450) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (88600) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (88610) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:3790202184 on exchange 45550r
I (90160) chip[IN]: Prepared unauthenticated message 0x3ffe75e4 to 0x0000000000000000 (0)  of type 0x23 and protocolId (0, 0) on exchange 45550r with MessageCounter:3310657553.
I (90170) chip[IN]: Sending unauthenticated msg 0x3ffe75e4 with MessageCounter:3310657553 to 0x0000000000000000 at monotonic time: 89396 msec
I (90190) NimBLE: GATT procedure initiated: notify; 
I (90190) NimBLE: att_handle=14

I (90200) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (90200) chip[DL]: Long dispatch time: 1599 ms, for event type 7
I (90310) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (90320) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:3790202185 on exchange 45550r
I (90330) chip[IN]: Prepared unauthenticated message 0x3ffe7664 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 45550r with MessageCounter:3310657554.
I (90340) chip[IN]: Sending unauthenticated msg 0x3ffe7664 with MessageCounter:3310657554 to 0x0000000000000000 at monotonic time: 89566 msec
I (90360) NimBLE: GATT procedure initiated: notify; 
I (90360) NimBLE: att_handle=14

I (90370) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (90370) chip[SVR]: Commissioning completed session establishment step
I (90390) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (90390) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (90400) chip[SVR]: Device completed Rendezvous process
I (90460) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (90470) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:15891883 on exchange 45551r
I (90480) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v
I (90480) chip[DMG]: AccessControl: implicit admin (PASE)
I (90500) chip[IN]: Prepared secure message 0x3ffe7904 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 45551r with MessageCounter:14318245.
I (90510) chip[IN]: Sending encrypted msg 0x3ffe7904 with MessageCounter:14318245 to 0xFFFFFFFB00000000 (0) at monotonic time: 89733 msec
I (90520) NimBLE: GATT procedure initiated: notify; 
I (90520) NimBLE: att_handle=14

I (90530) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (90580) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (90590) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:15891884 on exchange 45552r
I (90600) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v
I (90610) chip[DMG]: AccessControl: implicit admin (PASE)
I (90620) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v
I (90620) chip[DMG]: AccessControl: implicit admin (PASE)
I (90630) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v
I (90640) chip[DMG]: AccessControl: implicit admin (PASE)
I (90640) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v
I (90660) chip[DMG]: AccessControl: implicit admin (PASE)
I (90660) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v
I (90670) chip[DMG]: AccessControl: implicit admin (PASE)
I (90680) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v
I (90680) chip[DMG]: AccessControl: implicit admin (PASE)
I (90700) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v
I (90700) chip[DMG]: AccessControl: implicit admin (PASE)
I (90710) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v
I (90720) chip[DMG]: AccessControl: implicit admin (PASE)
I (90720) chip[IN]: Prepared secure message 0x3ffe7904 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 45552r with MessageCounter:14318246.
I (90740) chip[IN]: Sending encrypted msg 0x3ffe7904 with MessageCounter:14318246 to 0xFFFFFFFB00000000 (0) at monotonic time: 89960 msec
I (90750) NimBLE: GATT procedure initiated: notify; 
I (90760) NimBLE: att_handle=14

I (90770) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (90770) chip[DL]: Long dispatch time: 166 ms, for event type 3
I (90780) NimBLE: GATT procedure initiated: notify; 
I (90780) NimBLE: att_handle=14

I (90790) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (90880) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (90890) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891885 on exchange 45553r
I (90900) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=o
I (90900) chip[DMG]: AccessControl: implicit admin (PASE)
I (90920) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45553r with MessageCounter:14318247.
I (90930) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318247 to 0xFFFFFFFB00000000 (0) at monotonic time: 90152 msec
I (90940) NimBLE: GATT procedure initiated: notify; 
I (90940) NimBLE: att_handle=14

I (90960) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91030) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (91040) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891886 on exchange 45554r
I (91050) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=o
I (91050) chip[DMG]: AccessControl: implicit admin (PASE)
I (91070) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
I (91070) chip[DL]: NVS set: chip-config/country-code = "XX"
I (91080) chip[DL]: NVS set: chip-config/breadcrumb = 4 (0x4)
I (91090) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45554r with MessageCounter:14318248.
I (91100) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318248 to 0xFFFFFFFB00000000 (0) at monotonic time: 90321 msec
I (91110) NimBLE: GATT procedure initiated: notify; 
I (91110) NimBLE: att_handle=14

I (91130) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91180) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (91190) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891887 on exchange 45555r
I (91200) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I (91200) chip[DMG]: AccessControl: implicit admin (PASE)
I (91210) chip[ZCL]: OpCreds: Certificate Chain request received for PAI
I (91220) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45555r with MessageCounter:14318249.
I (91230) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318249 to 0xFFFFFFFB00000000 (0) at monotonic time: 90454 msec
I (91250) NimBLE: GATT procedure initiated: notify; 
I (91260) NimBLE: att_handle=14

I (91260) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91270) NimBLE: GATT procedure initiated: notify; 
I (91270) NimBLE: att_handle=14

I (91280) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91290) NimBLE: GATT procedure initiated: notify; 
I (91290) NimBLE: att_handle=14

I (91300) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91360) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (91370) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891888 on exchange 45556r
I (91380) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I (91380) chip[DMG]: AccessControl: implicit admin (PASE)
I (91390) chip[ZCL]: OpCreds: Certificate Chain request received for DAC
I (91400) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45556r with MessageCounter:14318250.
I (91410) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318250 to 0xFFFFFFFB00000000 (0) at monotonic time: 90634 msec
I (91430) NimBLE: GATT procedure initiated: notify; 
I (91440) NimBLE: att_handle=14

I (91440) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91450) NimBLE: GATT procedure initiated: notify; 
I (91450) NimBLE: att_handle=14

I (91460) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91470) NimBLE: GATT procedure initiated: notify; 
I (91470) NimBLE: att_handle=14

I (91480) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91540) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (91550) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891889 on exchange 45557r
I (91560) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I (91560) chip[DMG]: AccessControl: implicit admin (PASE)
I (91580) chip[ZCL]: OpCreds: received an AttestationRequest
I (91900) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45557r with MessageCounter:14318251.
I (91910) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318251 to 0xFFFFFFFB00000000 (0) at monotonic time: 91132 msec
I (91920) NimBLE: GATT procedure initiated: notify; 
I (91920) NimBLE: att_handle=14

I (91930) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (91940) chip[DL]: Long dispatch time: 395 ms, for event type 7
I (91940) NimBLE: GATT procedure initiated: notify; 
I (91950) NimBLE: att_handle=14

I (91960) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (91970) NimBLE: GATT procedure initiated: notify; 
I (91970) NimBLE: att_handle=14

I (91970) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (92170) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (92180) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891890 on exchange 45558r
I (92190) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I (92190) chip[DMG]: AccessControl: implicit admin (PASE)
I (92210) chip[ZCL]: OpCreds: commissioner has requested a CSR
I (93130) chip[ZCL]: OpCreds: NewCertificateSigningRequest returned 0
I (93450) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45558r with MessageCounter:14318252.
I (93470) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318252 to 0xFFFFFFFB00000000 (0) at monotonic time: 92688 msec
I (93480) NimBLE: GATT procedure initiated: notify; 
I (93480) NimBLE: att_handle=14

I (93480) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (93500) chip[DL]: Long dispatch time: 1320 ms, for event type 7
I (93500) NimBLE: GATT procedure initiated: notify; 
I (93510) NimBLE: att_handle=14

I (93510) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (93640) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (93820) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (93830) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891891 on exchange 45559r
I (93840) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I (93840) chip[DMG]: AccessControl: implicit admin (PASE)
I (93850) chip[ZCL]: OpCreds: commissioner has added a trusted root Cert
I (93860) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45559r with MessageCounter:14318253.
I (93870) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318253 to 0xFFFFFFFB00000000 (0) at monotonic time: 93094 msec
I (93880) NimBLE: GATT procedure initiated: notify; 
I (93900) NimBLE: att_handle=14

I (93900) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (93940) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (94000) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (94010) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891892 on exchange 45560r
I (94020) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I (94020) chip[DMG]: AccessControl: implicit admin (PASE)
I (94040) chip[ZCL]: OpCreds: commissioner has added a NOC
I (94040) chip[DIS]: Verifying the received credentials
I (94680) chip[DIS]: Added new fabric at index: 1, Initialized: 1
I (94680) chip[DIS]: Assigned compressed fabric ID: 0x4117F8F4D3431D45, node ID: 0x0000000000000012
I (94700) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (94700) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (94710) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000012, VendorId 0x1700
I (94720) chip[ZCL]: OpCreds: Call to fabricListChanged
I (94740) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I (94740) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 0000000000000012, VendorId 0x1700
I (94750) chip[ZCL]: OpCreds: Call to fabricListChanged
I (94770) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (94770) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (94780) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000012, VendorId 0x1700
I (94790) chip[ZCL]: OpCreds: Call to fabricListChanged
I (94810) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I (94810) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 0000000000000012, VendorId 0x1700
I (94820) chip[ZCL]: OpCreds: Call to fabricListChanged
I (94840) chip[DMG]: AccessControl: validating f=1 p=a a=c s=1 t=0
I (94840) chip[DMG]:   validating subject 0xC28EBF23EE21840D
I (94980) chip[ZCL]: OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0xC28EBF23EE21840D
I (94980) chip[DIS]: Advertise operational node 4117F8F4D3431D45-0000000000000012
I (94990) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (94990) chip[DIS]: mDNS service published: _matter._tcp
I (95000) chip[ZCL]: OpCreds: successfully added a NOC
I (95010) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 45560r with MessageCounter:14318254.
I (95020) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318254 to 0xFFFFFFFB00000000 (1) at monotonic time: 94243 msec
I (95030) NimBLE: GATT procedure initiated: notify; 
I (95050) NimBLE: att_handle=14

I (95050) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (95060) chip[DL]: Long dispatch time: 1055 ms, for event type 7
I (95080) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (95090) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891893 on exchange 45561r
I (95100) chip[DMG]: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=o
I (95100) chip[DMG]: AccessControl: implicit admin (PASE)
I (95120) chip[IN]: Prepared secure message 0x3ffe76f4 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 45561r with MessageCounter:14318255.
I (95130) chip[IN]: Sending encrypted msg 0x3ffe76f4 with MessageCounter:14318255 to 0xFFFFFFFB00000000 (1) at monotonic time: 94353 msec
I (95140) NimBLE: GATT procedure initiated: notify; 
I (95140) NimBLE: att_handle=14

I (95160) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (95200) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (95210) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15891894 on exchange 45562r
I (95220) chip[DMG]: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=o
I (95220) chip[DMG]: AccessControl: implicit admin (PASE)
I (95230) chip[NP]: ESP NetworkCommissioningDelegate: SSID: BelkinWemoLinksys
I (95240) chip[DL]: WiFi station mode change: Enabled -> Disabled
I (95290) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP
I (95290) wifi:mode : sta (b8:f0:09:c4:97:38) + softAP (8e:1d:d4:54:a9:e4)
I (95290) wifi:Total power save buffer number: 16
I (95290) wifi:Init max length of beacon: 752/752
I (95310) wifi:Init max length of beacon: 752/752
I (95320) chip[DL]: WiFi station mode change: Disabled -> Enabled
E (95320) chip[DL]: Long dispatch time: 115 ms, for event type 7
W (95320) wifi:Haven't to connect to a suitable AP now!
I (95330) chip[DL]: Attempting to connect WiFi station interface
I (95340) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (95350) chip[DL]: Done driving station state, nothing else to do...
W (95350) wifi:Haven't to connect to a suitable AP now!
I (95350) chip[DL]: Attempting to connect WiFi station interface
E (95360) wifi:sta is connecting, return error
E (95360) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
W (95380) wifi:Haven't to connect to a suitable AP now!
I (95380) chip[DL]: Attempting to connect WiFi station interface
E (95390) wifi:sta is connecting, return error
E (95390) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (95390) chip[DL]: WIFI_EVENT_AP_START
I (95400) chip[DL]: WiFi AP state change: NotActive -> Active
I (95400) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA
I (95420) wifi:mode : sta (b8:f0:09:c4:97:38)
I (95430) chip[DL]: WiFi AP state change: Active -> Deactivating
I (95430) app-devicecallbacks: Current free heap: 67892

I (95430) chip[DL]: WIFI_EVENT_AP_STOP
I (95440) chip[DL]: WiFi AP state change: Deactivating -> NotActive
I (95440) app-devicecallbacks: Current free heap: 67892

I (95830) wifi:new:<3,0>, old:<1,1>, ap:<255,255>, sta:<3,0>, prof:1
I (96580) wifi:state: init -> auth (b0)
I (96590) wifi:state: auth -> assoc (0)
I (96600) wifi:state: assoc -> run (10)
W (96610) wifi:<ba-add>idx:0 (ifx:0, c0:56:27:77:b6:a8), tid:0, ssn:0, winSize:64
I (96630) wifi:connected with BelkinWemoLinksys, aid = 2, channel 3, BW20, bssid = c0:56:27:77:b6:a8
I (96630) wifi:security: WPA2-PSK, phy: bgn, rssi: -5
I (96650) wifi:pm start, type: 1

I (96660) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (96660) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (96660) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (96670) chip[DL]: WiFi station interface connected
I (96680) chip[DIS]: Advertise operational node 4117F8F4D3431D45-0000000000000012
I (96690) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (96690) chip[DIS]: mDNS service published: _matter._tcp
I (96690) wifi:E (96700) chip[SVR]: Operational advertising enabled
AP's beacon interval = 102400 us, DTIM period = 1I (96700) app-devicecallbacks: Current free heap: 63788

I (96720) chip[IN]: Prepared secure message 0x3ffe78e4 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 45562r with MessageCounter:14318256.
I (96730) chip[IN]: Sending encrypted msg 0x3ffe78e4 with MessageCounter:14318256 to 0xFFFFFFFB00000000 (1) at monotonic time: 95955 msec
I (96750) NimBLE: GATT procedure initiated: notify; 
I (96750) NimBLE: att_handle=14

I (96760) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (96760) chip[DL]: Done driving station state, nothing else to do...
I (96770) app-devicecallbacks: Current free heap: 65484

E (96780) chip[DL]: Long dispatch time: 118 ms, for event type 49152
I (96790) chip[DL]: Updating advertising data
I (96790) app-devicecallbacks: Current free heap: 67004

I (97530) esp_netif_handlers: sta ip: 192.168.69.124, mask: 255.255.255.0, gw: 192.168.69.1
I (97530) chip[DL]: IP_EVENT_STA_GOT_IP
I (97530) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.69.124/255.255.255.0 gateway 192.168.69.1
I (97540) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (97560) app-devicecallbacks: Current free heap: 66980

I (97560) app-devicecallbacks: Server ready at: 192.168.69.124:5540
I (97570) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (97580) chip[DIS]: CHIP minimal mDNS started advertising.
I (97590) chip[DIS]: Advertise operational node 4117F8F4D3431D45-0000000000000012
I (97600) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (97610) chip[DIS]: mDNS service published: _matter._tcp
I (97610) chip[DIS]: Have operational credentials
I (97610) app-devicecallbacks: Current free heap: 66120

I (97630) chip[DIS]: CHIP minimal mDNS started advertising.
I (97630) chip[DIS]: Advertise operational node 4117F8F4D3431D45-0000000000000012
I (97630) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (97650) chip[DIS]: mDNS service published: _matter._tcp
I (97650) chip[DIS]: Have operational credentials
I (97660) app-devicecallbacks: Current free heap: 67428

I (97820) chip[EM]: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:3790202186 on exchange 45563r
I (97820) chip[IN]: CASE Server received Sigma1 message. Starting handshake. EC 0x3ffca1c8
I (97830) chip[DIS]: CASE handshake initiated, closing all BLE Connections
I (97840) chip[BLE]: Releasing end point's BLE connection back to application.
I (97850) chip[IN]: CASE Server disabling CASE session setups
I (97860) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (97860) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (97870) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000012, VendorId 0x1700
I (97880) chip[ZCL]: OpCreds: Call to fabricListChanged
I (97900) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (97900) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (97910) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000012, VendorId 0x1700
I (97930) chip[ZCL]: OpCreds: Call to fabricListChanged
I (98860) chip[IN]: Prepared unauthenticated message 0x3ffca0e4 to 0x0000000000000000 (0)  of type 0x31 and protocolId (0, 0) on exchange 45563r with MessageCounter:3310657555.
I (98870) chip[IN]: Sending unauthenticated msg 0x3ffca0e4 with MessageCounter:3310657555 to 0x0000000000000000 at monotonic time: 98096 msec
E (98890) chip[DL]: Long dispatch time: 1073 ms, for event type 3
I (98890) chip[DL]: IP_EVENT_GOT_IP6
I (98890) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:baf0:09ff:fec4:9738
I (98900) app-devicecallbacks: Current free heap: 56280

I (98920) chip[DIS]: CHIP minimal mDNS started advertising.
I (98930) chip[DIS]: Advertise operational node 4117F8F4D3431D45-0000000000000012
I (98930) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (98950) chip[DIS]: mDNS service published: _matter._tcp
I (98950) chip[DIS]: Have operational credentials
I (98950) app-devicecallbacks: Current free heap: 57724

I (99250) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:3790202187 on exchange 45563r
I (99340) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (100520) chip[IN]: Prepared unauthenticated message 0x3ffca0e4 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 45563r with MessageCounter:3310657556.
I (100530) chip[IN]: Sending unauthenticated msg 0x3ffca0e4 with MessageCounter:3310657556 to 0x0000000000000000 at monotonic time: 99754 msec
I (100550) chip[IN]: CASE Session established. Setting up the secure channel.
I (100550) chip[IN]: CASE secure channel is available now.
I (100560) chip[IN]: CASE Server enabling CASE session setups
E (100560) chip[DL]: Long dispatch time: 1316 ms, for event type 3
I (100580) chip[BLE]: Releasing end point's BLE connection back to application.
E (100580) chip[BLE]: HandleChipConnectionReceived failed, err = d
E (100590) chip[BLE]: failed handle new chip BLE connection, status = d
I (100690) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7771205 on exchange 45564r
I (100700) chip[DMG]: AccessControl: checking f=1 a=c s=0xC28EBF23EE21840D t= c=0x0000_0030 e=0 p=o
I (100710) chip[IN]: Prepared secure message 0x3ffca0fc to 0xC28EBF23EE21840D (1)  of type 0x9 and protocolId (0, 1) on exchange 45564r with MessageCounter:16456340.
I (100730) chip[IN]: Sending encrypted msg 0x3ffca0fc with MessageCounter:16456340 to 0xC28EBF23EE21840D (1) at monotonic time: 99948 msec
I (100740) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3790202188 on exchange 45563r
I (100760) chip[SVR]: Commissioning completed successfully
I (100760) chip[DIS]: CHIP minimal mDNS started advertising.
I (100770) chip[DIS]: Advertise operational node 4117F8F4D3431D45-0000000000000012
I (100770) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (100790) chip[DIS]: mDNS service published: _matter._tcp
I (100790) chip[DIS]: Have operational credentials
I (100790) app-devicecallbacks: Commissioning complete
I (100800) app-devicecallbacks: Current free heap: 59596

I (100890) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7771206 on exchange 45564r
I (100890) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:7771207 on exchange 45565r
I (100910) chip[DMG]: AccessControl: checking f=1 a=c s=0xC28EBF23EE21840D t= c=0x0000_001D e=0 p=v
I (100910) chip[IN]: Prepared secure message 0x3ffca0e4 to 0xC28EBF23EE21840D (1)  of type 0x5 and protocolId (0, 1) on exchange 45565r with MessageCounter:16456341.
I (100930) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:16456341 to 0xC28EBF23EE21840D (1) at monotonic time: 100148 msec
I (101000) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7771208 on exchange 45565r
I (101000) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:7771209 on exchange 45566r
I (101020) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:7771210 on exchange 45567r
I (101040) chip[DMG]: AccessControl: checking f=1 a=c s=0xC28EBF23EE21840D t= c=0x0000_001D e=1 p=v
I (101040) chip[IN]: Prepared secure message 0x3ffca0e4 to 0xC28EBF23EE21840D (1)  of type 0x5 and protocolId (0, 1) on exchange 45566r with MessageCounter:16456342.
I (101050) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:16456342 to 0xC28EBF23EE21840D (1) at monotonic time: 100275 msec
I (101070) chip[DMG]: AccessControl: checking f=1 a=c s=0xC28EBF23EE21840D t= c=0x0000_001D e=2 p=v
I (101080) chip[IN]: Prepared secure message 0x3ffca0fc to 0xC28EBF23EE21840D (1)  of type 0x5 and protocolId (0, 1) on exchange 45567r with MessageCounter:16456343.
I (101100) chip[IN]: Sending encrypted msg 0x3ffca0fc with MessageCounter:16456343 to 0xC28EBF23EE21840D (1) at monotonic time: 100319 msec
I (101110) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7771211 on exchange 45566r
I (106010) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:7771210 on exchange 45567r
I (106020) chip[IN]: Prepared secure message 0x3ffe7764 to 0xC28EBF23EE21840D (1)  of type 0x10 and protocolId (0, 0) on exchange 45567r with MessageCounter:16456344.
I (106030) chip[IN]: Sending encrypted msg 0x3ffe7764 with MessageCounter:16456344 to 0xC28EBF23EE21840D (1) at monotonic time: 105253 msec
I (106060) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:7771212 on exchange 45568r
I (106060) chip[DMG]: AccessControl: checking f=1 a=c s=0xC28EBF23EE21840D t= c=0x0000_003E e=0 p=v
I (106080) chip[IN]: Prepared secure message 0x3ffca0e4 to 0xC28EBF23EE21840D (1)  of type 0x5 and protocolId (0, 1) on exchange 45568r with MessageCounter:16456345.
I (106090) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:16456345 to 0xC28EBF23EE21840D (1) at monotonic time: 105312 msec
I (106110) chip[IN]: Sending encrypted msg 0x3ffca0fc with MessageCounter:16456343 to 0xC28EBF23EE21840D (1) at monotonic time: 105333 msec
I (106130) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7771213 on exchange 45568r
I (106130) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7771214 on exchange 45567r
I (106150) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7771215 on exchange 45569r
I (106160) chip[DMG]: AccessControl: checking f=1 a=c s=0xC28EBF23EE21840D t= c=0x0000_003E e=0 p=o
I (106170) chip[ZCL]: OpCreds: RemoveFabric
I (106180) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (106180) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (106190) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000012, VendorId 0x1700
I (106200) chip[ZCL]: OpCreds: Call to fabricListChanged
I (106230) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (106230) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (106240) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000012, VendorId 0x1700
I (106250) chip[ZCL]: OpCreds: Call to fabricListChanged
I (106250) chip[DIS]: Fabric (1) deleted. Calling OnFabricDeletedFromStorage
OpCredsFabricTableDelegate::OnFabricDeletedFromStorage
I (106270) chip[ZCL]: OpCreds: Fabric 0x1 was deleted from fabric storage.
I (106280) chip[ZCL]: OpCreds: Call to fabricListChanged
I (106280) chip[DIS]: CHIP minimal mDNS started advertising.
I (106300) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (106300) chip[DIS]: Start dns-sd server - no current nodeId
I (106320) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3674/14
I (106320) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (106340) chip[DIS]: mDNS service published: _matterc._udp
I (106340) chip[ZCL]: OpCreds: Call to fabricListChanged
I (106350) chip[IN]: Prepared secure message 0x3ffe7754 to 0xC28EBF23EE21840D (1)  of type 0x9 and protocolId (0, 1) on exchange 45569r with MessageCounter:16456346.
I (106360) chip[IN]: Sending encrypted msg 0x3ffe7754 with MessageCounter:16456346 to 0xC28EBF23EE21840D (1) at monotonic time: 105582 msec
E (106380) chip[DL]: Long dispatch time: 227 ms, for event type 3
E (106390) chip[IN]: Data received on an unknown session (LSID=2). Dropping it!
E (106390) chip[IN]: Data received on an unknown session (LSID=2). Dropping it!
I (106510) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0
E (106520) chip[BLE]: no endpoint for unsub recvd
I (106520) chip[DL]: CHIPoBLE unsubscribe received
I (106530) chip[DL]: BLE GAP connection terminated (con 0 reason 0x213)
I (106530) app-devicecallbacks: CHIPoBLE disconnected
I (106550) app-devicecallbacks: Current free heap: 67112

E (113390) chip[IN]: Data received on an unknown session (LSID=3). Dropping it!
E (118410) chip[IN]: Data received on an unknown session (LSID=3). Dropping it!
E (118720) chip[IN]: Data received on an unknown session (LSID=3). Dropping it!
E (119030) chip[IN]: Data received on an unknown session (LSID=3). Dropping it!
shubhamdp commented 2 years ago

Logs shows commissioning was successful

I (100760) chip[SVR]: Commissioning completed successfully

and

I (100790) app-devicecallbacks: Commissioning complete

Also, there were at least three type of actions were performed:

  1. Commissioning(it was successful)
  2. Some cluster control (can not decode what that was through the logs)
  3. Remove Fabric (and it seems to be successful)

Since these were back-to-back so thats why it looks like commissioning failure?

dhrishi commented 2 years ago

Also, @shubhamdp can you please verify using the manual code with the latest codebase

shubhamdp commented 2 years ago

@dhrishi tried with examples/temperature-measurement-app/esp32 with manual code and commissioning completed with success. temp-app-esp32.log chip-tool.log

woody-apple commented 2 years ago

Issue Scrub: Closing this given it sounds like this is confirmed working.