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

Commissioning device with qr code fails (CON-1494) #1226

Closed
herculesp17 opened this issue Jan 3, 2025 · 3 comments
Closed

Commissioning device with qr code fails (CON-1494) #1226

herculesp17 opened this issue Jan 3, 2025 · 3 comments

Comments

@herculesp17
Copy link

Describe the bug
I am trying to commission the sensor matter example on my esp32c6, but the commissiong fails.

Environment

  • ESP-Matter Commit Id:
    96b0939

  • ESP-IDF Commit Id:
    67c1de1eebe095d554d281952fde63c16ee2dca0

  • SoC (eg: ESP32 or ESP32-C3):
    esp32-c6

  • Device Logs (Please attach the log file):

  • Host Machine OS:
    EndeavourOS

  • Host Machine Python version:
    Python 3.12.7

Further Description
Steps to reproduce:

cd ~/esp/esp-matter/examples/sensors/
idf.py menuconfig

In the configuration menu, set the following additional configuration to use custom factory partition and different values for Data and Device Info Providers.

Enable ESP32 Factory Data Provider [Component config → CHIP Device Layer → Commissioning options → Use ESP32 Factory Data Provider]

Enable config option CONFIG_ENABLE_ESP32_FACTORY_DATA_PROVIDER to use ESP32 specific implementation of CommissionableDataProvider and DeviceAttestationCredentialsProvider.

Enable ESP32 Device Instance Info Provider [Component config → CHIP Device Layer → Commissioning options → Use ESP32 Device Instance Info Provider]

Enable config option ENABLE_ESP32_DEVICE_INSTANCE_INFO_PROVIDER to get device instance info from factory partition.

Enable Attestation - Factory [ Component config → ESP Matter → DAC Provider options → Attestation - Factory]

Enable config option CONFIG_FACTORY_PARTITION_DAC_PROVIDER to use DAC certificates from the factory partition during

Set chip-factory namespace partition label [Component config → CHIP Device Layer → Matter Manufacturing Options → chip-factory namespace partition label]

Set config option CHIP_FACTORY_NAMESPACE_PARTITION_LABEL to choose the label of the partition to store key-values in the "chip-factory" namespace. The default chosen partition label is nvs.

Generate a factory partition

esp-matter-mfg-tool -cn "My sensor" -v 0xFFF2 -p 0x8001 --pai \
    -k $MATTER_SDK_PATH/credentials/test/attestation/Chip-Test-PAI-FFF2-8001-Key.pem \
    -c $MATTER_SDK_PATH/credentials/test/attestation/Chip-Test-PAI-FFF2-8001-Cert.pem \
    -cd $MATTER_SDK_PATH/credentials/test/certification-declaration/Chip-Test-CD-FFF2-8001.der
  1. idf.py erase-flash
  2. idf.py flash -p /dev/ttyACM0
esptool.py -p /dev/ttyACM0 write_flash 0x10000 out/fff2_8001/a0505a6b-1ec5-4454-8948-afa79ecb6ed8/a0505a6b-1ec5-4454-8948-afa79ecb6ed8-partition.bin
  • Commissiong Logs (i ran idf.py monitor and the tried scanned the qr code for commissioning and these are the logs)
Detecting chip type... ESP32-C6
Running idf_monitor in directory /home/lennart/esp/esp-matter/examples/sensors
Executing "/home/lennart/.espressif/python_env/idf5.4_py3.12_env/bin/python /home/lennart/esp/esp-idf/tools/idf_monitor.py -p /dev/ttyACM0 -b 115200 --toolchain-prefix riscv32-esp-elf- --target esp32c6 --revision 0 --decode-panic backtrace /home/lennart/esp/esp-matter/examples/sensors/build/sensors.elf -m '/home/lennart/.espressif/python_env/idf5.4_py3.12_env/bin/python' '/home/lennart/esp/esp-idf/tools/idf.py'"...
--- esp-idf-monitor 1.5.0 on /dev/ttyACM0 115200
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H
ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x1e (SPI_FAST_FLASH_BOOT)
Saved PC:0x400228e0
--- 0x400228e0: usb_serial_device_rx_one_char in ROM

SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len:0x16b8
load:0x4086c110,len:0xe84
load:0x4086e610,len:0x3048
entry 0x4086c11a
I (23) boot: ESP-IDF v5.4 2nd stage bootloader
I (23) boot: compile time Jan  3 2025 15:24:34
I (24) boot: chip revision: v0.1
I (24) boot: efuse block revision: v0.3
I (26) boot.esp32c6: SPI Speed      : 80MHz
I (30) boot.esp32c6: SPI Mode       : DIO
I (34) boot.esp32c6: SPI Flash Size : 4MB
I (38) boot: Enabling RNG early entropy source...
I (42) boot: Partition Table:
I (45) boot: ## Label            Usage          Type ST Offset   Length
I (51) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
I (58) boot:  1 nvs              WiFi data        01 02 00010000 0000c000
I (64) boot:  2 nvs_keys         NVS keys         01 04 0001c000 00001000
I (71) boot:  3 otadata          OTA data         01 00 0001d000 00002000
I (77) boot:  4 phy_init         RF data          01 01 0001f000 00001000
I (84) boot:  5 ota_0            OTA app          00 10 00020000 001e0000
I (90) boot:  6 ota_1            OTA app          00 11 00200000 001e0000
I (97) boot:  7 fctry            WiFi data        01 02 003e0000 00006000
I (103) boot: End of partition table
I (107) esp_image: segment 0: paddr=00020020 vaddr=42140020 size=37f94h (229268) map
I (156) esp_image: segment 1: paddr=00057fbc vaddr=40800000 size=0805ch ( 32860) load
I (164) esp_image: segment 2: paddr=00060020 vaddr=42000020 size=13bedch (1294044) map
I (403) esp_image: segment 3: paddr=0019bf04 vaddr=4080805c size=16994h ( 92564) load
I (424) esp_image: segment 4: paddr=001b28a0 vaddr=4081e9f0 size=04220h ( 16928) load
I (428) esp_image: segment 5: paddr=001b6ac8 vaddr=50000000 size=0001ch (    28) load
I (436) boot: Loaded app from partition at offset 0x20000
I (437) boot: Disabling RNG early entropy source...
I (449) cpu_start: Unicore app
I (458) cpu_start: Pro cpu start user code
I (458) cpu_start: cpu freq: 160000000 Hz
I (458) app_init: Application information:
I (458) app_init: Project name:     sensors
I (462) app_init: App version:      1.0
I (465) app_init: Compile time:     Jan  3 2025 15:33:24
I (470) app_init: ELF file SHA256:  33d2daab2...
I (475) app_init: ESP-IDF:          v5.4
I (478) efuse_init: Min chip rev:     v0.0
I (482) efuse_init: Max chip rev:     v0.99
I (486) efuse_init: Chip rev:         v0.1
I (490) heap_init: Initializing. RAM available for dynamic allocation:
I (496) heap_init: At 40836B90 len 00045A80 (278 KiB): RAM
I (501) heap_init: At 4087C610 len 00002F54 (11 KiB): RAM
I (506) heap_init: At 5000001C len 00003FCC (15 KiB): RTCRAM
I (513) spi_flash: detected chip: generic
I (516) spi_flash: flash io: dio
W (519) i2c: This driver is an old driver, please migrate your application code to adapt `driver/i2c_master.h`
I (530) sleep_gpio: Configure to isolate all GPIO pins in sleep state
I (535) sleep_gpio: Enable automatic switching of GPIO sleep configuration
I (541) coexist: coex firmware version: 49a8cdc
I (545) coexist: coexist rom version 5b8dcfa
I (550) main_task: Started on CPU0
I (550) main_task: Calling app_main()
I (570) button: IoT Button Version: 3.4.1
I (570) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (580) shtc3: shtc3 initialized successfully
E (580) esp_matter_cluster: Config is NULL or mandatory features are missing.
I (580) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (590) pp: pp rom version: 5b8dcfa
I (600) net80211: net80211 rom version: 5b8dcfa
I (610) wifi:wifi driver task: 40843278, prio:23, stack:6656, core=0
I (610) wifi:wifi firmware version: 48ea317a7
I (610) wifi:wifi certification version: v7.0
I (610) wifi:config NVS flash: enabled
I (620) wifi:config nano formatting: disabled
I (620) wifi:mac_version:HAL_MAC_ESP32AX_761,ut_version:N, band mode:0x1
I (630) wifi:Init data frame dynamic rx buffer num: 32
I (630) wifi:Init static rx mgmt buffer num: 5
I (640) wifi:Init management short buffer num: 32
I (640) wifi:Init dynamic tx buffer num: 32
I (640) wifi:Init static tx FG buffer num: 2
I (650) wifi:Init static rx buffer size: 1700 (rxctrl:92, csi:512)
I (650) wifi:Init static rx buffer num: 10
I (660) wifi:Init dynamic rx buffer num: 32
I (660) wifi_init: rx ba win: 6
I (670) wifi_init: accept mbox: 6
I (670) wifi_init: tcpip mbox: 32
I (670) wifi_init: udp mbox: 6
I (670) wifi_init: tcp mbox: 6
I (680) wifi_init: tcp tx win: 5760
I (680) wifi_init: tcp rx win: 5760
I (680) wifi_init: tcp mss: 1440
I (690) wifi_init: WiFi IRAM OP enabled
I (690) wifi_init: WiFi RX IRAM OP enabled
I (690) wifi_init: WiFi SLP IRAM OP enabled
I (720) chip[DL]: NVS set: chip-counters/reboot-count = 4 (0x4)
I (720) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (720) BLE_INIT: Using main XTAL as clock source
I (730) BLE_INIT: ble controller commit:[b623f7a]
I (730) BLE_INIT: Bluetooth MAC: 54:32:04:11:cf:c6
I (730) phy_init: phy_version 320,348a293,Sep  3 2024,16:33:12
I (820) phy: libbtbb version: 04952fd, Sep  3 2024, 16:33:30
I (820) NimBLE: GAP procedure initiated: stop advertising.

I (820) NimBLE: Failed to restore IRKs from store; status=8

I (820) CHIP[DL]: BLE host-controller synced
I (1330) chip[DL]: Starting ESP WiFi layer
W (1330) wifi:ACK_TAB0   :0x   90a0b, QAM16:0x9 (24Mbps), QPSK:0xa (12Mbps), BPSK:0xb (6Mbps)
W (1330) wifi:CTS_TAB0   :0x   90a0b, QAM16:0x9 (24Mbps), QPSK:0xa (12Mbps), BPSK:0xb (6Mbps)
W (1330) wifi:(agc)0x600a7128:0xd214b9ee, min.avgNF:0xce->0xd2(dB), RCalCount:0x14a, min.RRssi:0x9ee(-97.12)
W (1340) wifi:(TB)WDEV_PWR_TB_MCS0:19
W (1350) wifi:(TB)WDEV_PWR_TB_MCS1:19
W (1350) wifi:(TB)WDEV_PWR_TB_MCS2:19
W (1350) wifi:(TB)WDEV_PWR_TB_MCS3:19
W (1360) wifi:(TB)WDEV_PWR_TB_MCS4:19
W (1360) wifi:(TB)WDEV_PWR_TB_MCS5:19
W (1360) wifi:(TB)WDEV_PWR_TB_MCS6:18
W (1370) wifi:(TB)WDEV_PWR_TB_MCS7:18
W (1370) wifi:(TB)WDEV_PWR_TB_MCS8:17
W (1370) wifi:(TB)WDEV_PWR_TB_MCS9:15
W (1380) wifi:(TB)WDEV_PWR_TB_MCS10:15
W (1380) wifi:(TB)WDEV_PWR_TB_MCS11:15
I (1390) wifi:11ax coex: WDEVAX_PTI0(0x55777555), WDEVAX_PTI1(0x00003377).

I (1390) wifi:mode : sta (54:32:04:11:cf:c4)
I (1400) wifi:enable tsf
I (1400) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 43
W (1400) wifi:Haven't to connect to a suitable AP now!
I (1410) chip[DL]: Attempting to connect WiFi station interface
I (1420) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 2
I (1420) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (1420) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1, snd_ch_cfg:0x0
I (1440) wifi:(connect)dot11_authmode:0x3, pairwise_cipher:0x3, group_cipher:0x3
I (1440) wifi:state: init -> auth (0xb0)
E (1450) chip[DMG]: Endpoint 0, Cluster 0x0000_0031 not found in IncreaseClusterDataVersion!
E (1450) chip[DMG]: Endpoint 0, Cluster 0x0000_0031 not found in IncreaseClusterDataVersion!
I (1460) chip[DL]: Done driving station state, nothing else to do...
I (1470) chip[SVR]: Initializing subscription resumption storage...
I (1460) wifi:state: auth -> assoc (0x0)
I (1480) chip[SVR]: Server initializing...
I (1480) chip[TS]: Last Known Good Time: 2025-01-03T14:55:54
I (1490) chip[DMG]: AccessControl: initializing
I (1490) chip[DMG]: Examples::AccessControlDelegate::Init
I (1500) chip[DMG]: AccessControl: setting
I (1500) chip[DMG]: DefaultAclStorage: initializing
I (1500) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1510) chip[SVR]: WARNING: mTestEventTriggerDelegate is null
I (1500) wifi:(assoc)RESP, Extended Capabilities length:8, operating_mode_notification:0
I (1520) wifi:(assoc)RESP, Extended Capabilities, MBSSID:0, TWT Responder:0, OBSS Narrow Bandwidth RU In OFDMA Tolerance:0
I (1540) wifi:Extended Capabilities length:8, operating_mode_notification:1
I (1540) wifi:state: assoc -> run (0x10)
I (1550) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 43
I (1560) chip[ZCL]: Using ZAP configuration...
I (1560) esp_matter_cluster: Cluster plugin init common callback
I (1560) chip[DMG]: AccessControlCluster: initializing
I (1570) chip[ZCL]: 0x42145b54 ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (1570) chip[ZCL]: Initiating Admin Commissioning cluster.
I (1580) chip[DIS]: Updating services using commissioning mode 1
I (1580) chip[DIS]: CHIP minimal mDNS started advertising.
I (1590) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=2156/08 cm=1 cp=0
I (1600) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: F04DD5D1FE008C38.
I (1610) chip[DIS]: mDNS service published: _matterc._udp
I (1610) chip[IN]: CASE Server enabling CASE session setups
I (1620) chip[SVR]: Joining Multicast groups
I (1620) chip[SVR]: Server Listening...
I (1630) esp_matter_core: Dynamic endpoint 0 added
I (1630) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (1640) esp_matter_core: Dynamic endpoint 1 added
I (1650) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (1660) esp_matter_core: Dynamic endpoint 2 added
I (1660) esp_matter_attribute: ********** R : Endpoint 0x0003's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (1670) esp_matter_attribute: ********** R : Endpoint 0x0003's Cluster 0x00000406's Attribute 0x00000001 is 0 **********
I (1680) esp_matter_attribute: ********** R : Endpoint 0x0003's Cluster 0x00000406's Attribute 0x00000002 is 1 **********
I (1690) esp_matter_core: Dynamic endpoint 3 added
I (1700) chip[DL]: WIFI_EVENT_STA_START
I (1570) wifi:(trc)phytype:CBW20-SGI, snr:14, maxRate:144, highestRateIdx:0
W (1710) wifi:(trc)band:2G, phymode:3, highestRateIdx:0, lowestRateIdx:11, dataSchedTableSize:14
I (1720) wifi:(trc)band:2G, rate(L-MCS2, rateIdx:6), ampdu(rate:L-MCS2, schedIdx(6, stop:8)), snr:14, ampduState:wait operational
I (1730) wifi:ifidx:0, rssi:-83, nf:-97, phytype(0x3, CBW20-SGI), phymode(0x3, 11bgn), max_rate:144, he:0, vht:0, ht:1
I (1740) wifi:(ht)max.RxAMPDULenExponent:3(65535 bytes), MMSS:0(no restriction)
I (1750) chip[DL]: Attempting to connect WiFi station interface
E (1750) wifi:sta is connecting, return error
E (1760) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (1760) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1770) wifi:connected with FRITZ!Box 7583 DB, aid = 1, channel 6, BW20, bssid = d4:24:dd:00:aa:98
I (1780) wifi:security: WPA2-PSK, phy:11bgn, rssi:-83, cipher(pairwise:0x3, group:0x3), pmf:0,
I (1790) wifi:pm start, type: 1, twt_start:0

I (1790) wifi:pm start, type:1, aid:0x1, trans-BSSID:d4:24:dd:00:aa:98, BSSID[5]:0x98, mbssid(max-indicator:0, index:0), he:0
I (1800) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (1810) wifi:set rx beacon pti, rx_bcn_pti: 10, bcn_timeout: 25000, mt_pti: 10, mt_time: 10000
I (1820) wifi:[ADDBA]TX addba request, tid:0, dialogtoken:1, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (1830) wifi:[ADDBA]TX addba request, tid:7, dialogtoken:2, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x20)
I (1840) wifi:[ADDBA]TX addba request, tid:5, dialogtoken:3, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (1780) NimBLE: GAP procedure initiated: advertise;
I (1850) NimBLE: disc_mode=2
I (1860) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1870) NimBLE:

I (1850) wifi:[ADDBA]RX addba response, status:0, tid:0/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
I (1880) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (1880) wifi:[ADDBA]RX addba response, status:0, tid:7/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
I (1890) wifi:[ADDBA]RX addba response, status:0, tid:5/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
I (1890) chip[DL]: CHIPoBLE advertising started
I (1910) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 4
I (1910) main_task: Returned from app_main()
I (1910) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (1920) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (1930) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (1930) chip[DL]: WiFi station interface connected
I (1940) chip[DL]: Done driving station state, nothing else to do...
I (1940) chip[DL]: Updating advertising data
I (1950) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1960) chip[DL]: Device already advertising, stop active advertisement and restart
I (1960) NimBLE: GAP procedure initiated: stop advertising.

W (1960) wifi:<ba-add>idx:0, ifx:0, tid:6, TAHI:0x10098aa, TALO:0xdd24d4, (ssn:2, win:64, cur_ssn:2), CONF:0xc0006005
I (1980) NimBLE: GAP procedure initiated: advertise;
I (1980) NimBLE: disc_mode=2
I (1990) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2000) NimBLE:

I (3090) esp_netif_handlers: sta ip: 192.168.178.34, mask: 255.255.255.0, gw: 192.168.178.1
I (3090) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 0
I (3090) chip[DL]: IP_EVENT_STA_GOT_IP
I (3090) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.178.34/255.255.255.0 gateway 192.168.178.1
I (3100) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (3110) chip[DIS]: Updating services using commissioning mode 1
I (3110) chip[DIS]: CHIP minimal mDNS started advertising.
I (3120) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=2156/08 cm=1 cp=0
I (3130) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: F04DD5D1FE008C38.
I (3140) chip[DIS]: mDNS service published: _matterc._udp
I (3590) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 3
I (3590) chip[DL]: IP_EVENT_GOT_IP6
I (3590) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:5632:04ff:fe11:cfc4
I (3590) chip[DIS]: Updating services using commissioning mode 1
I (3600) chip[DIS]: CHIP minimal mDNS started advertising.
I (3610) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=2156/08 cm=1 cp=0
I (3620) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: F04DD5D1FE008C38.
I (3630) chip[DIS]: mDNS service published: _matterc._udp
I (3630) chip[SVR]: Server initialization complete
I (3630) chip[DIS]: Updating services using commissioning mode 1
I (3640) chip[DIS]: CHIP minimal mDNS started advertising.
I (3650) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=2156/08 cm=1 cp=0
I (3660) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: F04DD5D1FE008C38.
I (3670) chip[DIS]: mDNS service published: _matterc._udp
I (3670) chip[SWU]: Stopping the watchdog timer
I (3670) chip[SWU]: Starting the periodic query timer, timeout: 86400 seconds
I (3680) chip[IM]: No subscriptions to resume
I (3690) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000002 is 0 **********
I (3700) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000002 is 0 **********
I (3710) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000002 is 1 **********
I (3720) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000003 is null **********
I (5590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is null **********
I (5590) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (5600) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is null **********
I (5610) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (5640) ROUTE_HOOK: Received RIO
I (5640) ROUTE_HOOK: prefix :: lifetime 1800
I (5650) ROUTE_HOOK: Received RIO
I (5650) ROUTE_HOOK: prefix 2001:8E0:3040:1C00:: lifetime 1800
W (5650) wifi:<ba-add>idx:1, ifx:0, tid:0, TAHI:0x10098aa, TALO:0xdd24d4, (ssn:0, win:64, cur_ssn:0), CONF:0xc0000005
I (7590) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 3
I (7590) chip[DL]: IP_EVENT_GOT_IP6
I (7590) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: 2001:08e0:3040:1c01:5632:04ff:fe11:cfc4
I (7590) chip[DL]: IPv6 Internet connectivity ESTABLISHED
I (7600) ROUTE_HOOK: Hook already installed on netif, skip...
I (7600) chip[DIS]: Updating services using commissioning mode 1
I (7610) chip[DIS]: CHIP minimal mDNS started advertising.
I (7620) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=2156/08 cm=1 cp=0
I (7630) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: F04DD5D1FE008C38.
I (7640) chip[DIS]: mDNS service published: _matterc._udp
I (10590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (10590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (15590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (15590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (20590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (20590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (25590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (25590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (30590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (30590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (31580) chip[DL]: bleAdv Timeout : Start slow advertisement
I (31580) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)
I (31580) chip[DL]: Device already advertising, stop active advertisement and restart
I (31590) NimBLE: GAP procedure initiated: stop advertising.

I (31590) NimBLE: GAP procedure initiated: advertise;
I (31600) NimBLE: disc_mode=2
I (31600) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (31610) NimBLE:

I (35590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (35590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (40590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (40590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (45590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (45590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (50590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (50590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (55590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (55590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (60590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (60590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (65590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (65590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (70590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (70590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (75590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (75590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (80590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (80590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (84100) chip[DL]: BLE GAP connection established (con 0)
I (84100) chip[DL]: CHIPoBLE advertising stopped
I (85120) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (85120) chip[BLE]: local and remote recv window sizes = 5
I (85120) chip[BLE]: selected BTP version 4
I (85120) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (85360) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 1
I (85360) chip[DL]: CHIPoBLE subscribe received
I (85360) NimBLE: GATT procedure initiated: indicate;
I (85360) NimBLE: att_handle=18

I (85420) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (85420) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (85420) chip[EM]: >>> [E:27648r S:0 M:55225885] (U) Msg RX from 0:A4722E211BB3F9F5 [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:68)
I (85440) chip[EM]: <<< [E:27648r S:0 M:257532428] (U) Msg TX from 0000000000000000 to 0:A4722E211BB3F9F5 [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:170)
I (85450) NimBLE: GATT procedure initiated: indicate;
I (85460) NimBLE: att_handle=18

I (85460) chip[SVR]: Commissioning session establishment step started
I (85510) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (85590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (85590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (86200) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (86200) chip[EM]: >>> [E:27648r S:0 M:55225886] (U) Msg RX from 0:A4722E211BB3F9F5 [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:92)
I (86270) chip[EM]: <<< [E:27648r S:0 M:257532429] (U) Msg TX from 0000000000000000 to 0:A4722E211BB3F9F5 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:127)
I (86270) NimBLE: GATT procedure initiated: indicate;
I (86270) NimBLE: att_handle=18

I (86350) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (86350) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (86350) chip[EM]: >>> [E:27648r S:0 M:55225887] (U) Msg RX from 0:A4722E211BB3F9F5 [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:59)
I (86370) chip[EM]: <<< [E:27648r S:0 M:257532430] (U) Msg TX from 0000000000000000 to 0:A4722E211BB3F9F5 [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport) (B:30)
I (86380) NimBLE: GATT procedure initiated: indicate;
I (86390) NimBLE: att_handle=18

I (86390) chip[SC]: SecureSession[0x40825e40, LSID:43925]: State change 'kEstablishing' --> 'kActive'
I (86400) chip[SVR]: Commissioning completed session establishment step
I (86400) chip[DIS]: Updating services using commissioning mode 0
I (86410) chip[DIS]: CHIP minimal mDNS started advertising.
I (86420) chip[SVR]: Device completed Rendezvous process
I (86470) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (86470) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (86470) chip[EM]: >>> [E:27649r S:43925 M:169097978] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
I (86490) chip[EM]: <<< [E:27649r S:43925 M:182889477] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:72)
I (86500) NimBLE: GATT procedure initiated: indicate;
I (86500) NimBLE: att_handle=18

I (86590) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (86590) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (86590) chip[EM]: >>> [E:27650r S:43925 M:169097979] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
I (86610) chip[EM]: <<< [E:27650r S:43925 M:182889478] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:86)
I (86620) NimBLE: GATT procedure initiated: indicate;
I (86620) NimBLE: att_handle=18

I (86710) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (86710) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (86710) chip[EM]: >>> [E:27651r S:43925 M:169097980] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:52)
I (86730) chip[EM]: <<< [E:27651r S:43925 M:182889479] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:67)
I (86740) NimBLE: GATT procedure initiated: indicate;
I (86740) NimBLE: att_handle=18

I (86800) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (86800) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (86800) chip[EM]: >>> [E:27652r S:43925 M:169097981] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
I (86820) chip[EM]: <<< [E:27652r S:43925 M:182889480] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:66)
I (86830) NimBLE: GATT procedure initiated: indicate;
I (86830) NimBLE: att_handle=18

I (86890) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (86890) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (86890) chip[EM]: >>> [E:27653r S:43925 M:169097982] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I (89390) NimBLE: GATT procedure initiated: indicate;
I (89390) NimBLE: att_handle=18

I (89440) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (90590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (90590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (91710) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 1
I (91710) chip[DL]: WIFI_EVENT_SCAN_DONE
I (91720) chip[EM]: <<< [E:27653r S:43925 M:182889481] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:192)
I (91730) NimBLE: GATT procedure initiated: indicate;
I (91730) NimBLE: att_handle=18

I (91810) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (91930) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (92200) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (92200) chip[EM]: >>> [E:27654r S:43925 M:169097983] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
I (92210) chip[EM]: <<< [E:27654r S:43925 M:182889482] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:72)
I (92220) NimBLE: GATT procedure initiated: indicate;
I (92230) NimBLE: att_handle=18

I (92290) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (92290) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (92290) chip[EM]: >>> [E:27655r S:43925 M:169097984] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
I (92310) chip[EM]: <<< [E:27655r S:43925 M:182889483] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:86)
I (92320) NimBLE: GATT procedure initiated: indicate;
I (92320) NimBLE: att_handle=18

I (92380) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (92380) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (92380) chip[EM]: >>> [E:27656r S:43925 M:169097985] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
I (92400) chip[EM]: <<< [E:27656r S:43925 M:182889484] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:90)
I (92410) NimBLE: GATT procedure initiated: indicate;
I (92410) NimBLE: att_handle=18

I (92470) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (92470) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (92470) chip[EM]: >>> [E:27657r S:43925 M:169097986] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:123)
I (92490) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 **********
I (92500) chip[EM]: <<< [E:27657r S:43925 M:182889485] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:258)
I (92510) NimBLE: GATT procedure initiated: indicate;
I (92520) NimBLE: att_handle=18

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

I (92620) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (92620) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (92620) chip[EM]: >>> [E:27658r S:43925 M:169097987] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I (92640) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030
I (92640) chip[FS]: GeneralCommissioning: Received ArmFailSafe (60s)
I (92650) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 **********
I (92660) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 3 **********
I (92670) chip[EM]: <<< [E:27658r S:43925 M:182889486] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (92690) NimBLE: GATT procedure initiated: indicate;
I (92690) NimBLE: att_handle=18

I (92740) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (92740) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (92740) chip[EM]: >>> [E:27659r S:43925 M:169097988] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I (92760) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x00000030
I (92770) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
I (92770) chip[DL]: NVS set: chip-config/country-code = "XX"
I (92780) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 3 **********
I (92790) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 4 **********
I (92800) chip[EM]: <<< [E:27659r S:43925 M:182889487] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (92810) NimBLE: GATT procedure initiated: indicate;
I (92820) NimBLE: att_handle=18

I (92860) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (92860) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (92860) chip[EM]: >>> [E:27660r S:43925 M:169097989] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I (92880) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E
I (92880) chip[ZCL]: OpCreds: Certificate Chain request received for PAI
I (92900) chip[EM]: <<< [E:27660r S:43925 M:182889488] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:513)
I (92910) NimBLE: GATT procedure initiated: indicate;
I (92910) NimBLE: att_handle=18

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

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

I (93130) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (93130) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (93130) chip[EM]: >>> [E:27661r S:43925 M:169097990] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I (93150) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E
I (93150) chip[ZCL]: OpCreds: Certificate Chain request received for DAC
I (93170) chip[EM]: <<< [E:27661r S:43925 M:182889489] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:574)
I (93180) NimBLE: GATT procedure initiated: indicate;
I (93180) NimBLE: att_handle=18

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

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

I (93430) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (93430) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (93430) chip[EM]: >>> [E:27662r S:43925 M:169097991] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I (93450) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x0000003E
I (93450) chip[ZCL]: OpCreds: Received an AttestationRequest command
I (93480) chip[ZCL]: OpCreds: AttestationRequest successful.
I (93480) chip[EM]: <<< [E:27662r S:43925 M:182889490] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:409)
I (93490) NimBLE: GATT procedure initiated: indicate;
I (93490) NimBLE: att_handle=18

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

I (93640) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (93700) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (93700) chip[EM]: >>> [E:27663r S:43925 M:169097992] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I (93710) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030
I (93720) chip[FS]: GeneralCommissioning: Received ArmFailSafe (60s)
I (93720) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 4 **********
I (93730) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 8 **********
I (93740) chip[EM]: <<< [E:27663r S:43925 M:182889491] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (93760) NimBLE: GATT procedure initiated: indicate;
I (93760) NimBLE: att_handle=18

I (93820) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (95530) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (95530) chip[EM]: >>> [E:27664r S:43925 M:169097993] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I (95540) esp_matter_command: Received command 0x00000004 for endpoint 0x0000's cluster 0x0000003E
I (95550) chip[ZCL]: OpCreds: Received a CSRRequest command
I (95580) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded
I (95600) chip[ZCL]: OpCreds: CSRRequest successful.
I (95600) chip[EM]: <<< [E:27664r S:43925 M:182889492] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:373)
I (95610) NimBLE: GATT procedure initiated: indicate;
I (95610) NimBLE: att_handle=18

I (95610) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (95620) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (95650) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (95650) NimBLE: GATT procedure initiated: indicate;
I (95650) NimBLE: att_handle=18

I (95710) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (95770) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (95830) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (95830) chip[EM]: >>> [E:27665r S:43925 M:169097994] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:316)
I (95840) esp_matter_command: Received command 0x0000000B for endpoint 0x0000's cluster 0x0000003E
I (95850) chip[ZCL]: OpCreds: Received an AddTrustedRootCertificate command
I (95880) chip[ZCL]: OpCreds: AddTrustedRootCertificate successful.
I (95880) chip[EM]: <<< [E:27665r S:43925 M:182889493] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:63)
I (95890) NimBLE: GATT procedure initiated: indicate;
I (95900) NimBLE: att_handle=18

I (95980) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (95980) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (96040) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (96040) chip[EM]: >>> [E:27666r S:43925 M:169097995] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:356)
I (96050) esp_matter_command: Received command 0x00000006 for endpoint 0x0000's cluster 0x0000003E
I (96060) chip[ZCL]: OpCreds: Received an AddNOC command
I (96060) chip[FP]: Validating NOC chain
I (96090) chip[FP]: NOC chain validation successful
I (96100) chip[FP]: Added new fabric at index: 0x2
I (96100) chip[FP]: Assigned compressed fabric ID: 0x74F274549D50DA25, node ID: 0x00000000A20E7E35
I (96100) chip[TS]: Last Known Good Time: 2025-01-03T14:55:54
I (96110) chip[TS]: New proposed Last Known Good Time: 2025-01-03T14:59:09
I (96110) chip[TS]: Updating pending Last Known Good Time to 2025-01-03T14:59:09
I (96140) chip[ZCL]: OpCreds: ACL entry created for Fabric index 0x2 CASE Admin Subject 0x38DCD9F1C5694B8D
I (96140) chip[DIS]: Advertise operational node 74F274549D50DA25-00000000A20E7E35
I (96140) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 74F274549D50DA25-00000000A20E7E35.
I (96150) chip[DIS]: mDNS service published: _matter._tcp
I (96160) chip[ZCL]: OpCreds: successfully created fabric index 0x2 via AddNOC
I (96170) chip[EM]: <<< [E:27666r S:43925 M:182889494] (S) Msg TX from 0000000000000000 to 2:FFFFFFFB00000000 [DA25] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (96180) NimBLE: GATT procedure initiated: indicate;
I (96180) NimBLE: att_handle=18

I (96250) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14
I (96250) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 16
I (96250) chip[EM]: >>> [E:27667r S:43925 M:169097996] (S) Msg RX from 2:FFFFFFFB00000000 [DA25] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I (96270) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030
I (96280) chip[FS]: GeneralCommissioning: Received ArmFailSafe (0s)
I (96280) chip[FS]: Fail-safe timer expired
I (96290) chip[EM]: <<< [E:27667r S:43925 M:182889495] (S) Msg TX from 0000000000000000 to 2:FFFFFFFB00000000 [DA25] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (96300) NimBLE: GATT procedure initiated: indicate;
I (96300) NimBLE: att_handle=18

E (96310) chip[SVR]: Failsafe timer expired
I (96310) chip[SC]: SecureSession[0x40825e40, LSID:43925]: State change 'kActive' --> 'kPendingEviction'
E (96320) chip[SVR]: Commissioning failed (attempt 1): 32
I (96330) chip[BLE]: Releasing end point's BLE connection back to application.
I (96330) chip[DL]: Closing BLE GATT connection (con 0)
I (96340) NimBLE: GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19

I (96350) chip[DIS]: Updating services using commissioning mode 1
I (96350) chip[DIS]: CHIP minimal mDNS started advertising.
I (96360) chip[DIS]: Advertise operational node 74F274549D50DA25-00000000A20E7E35
I (96360) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 74F274549D50DA25-00000000A20E7E35.
I (96380) chip[DIS]: mDNS service published: _matter._tcp
I (96380) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=2156/08 cm=1 cp=0
I (96390) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: F04DD5D1FE008C38.
I (96410) chip[DIS]: mDNS service published: _matterc._udp
E (96410) chip[ZCL]: OpCreds: Got FailSafeTimerExpired
E (96410) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
E (96420) chip[FP]: Reverting pending fabric data for fabric 0x2
E (96420) chip[FP]: Warning: metadata not found during delete of fabric 0x2
I (96430) chip[FP]: Fabric (0x2) deleted.
I (96430) chip[ZCL]: OpCreds: Fabric index 0x2 was removed
I (96440) chip[DIS]: Updating services using commissioning mode 1
I (96450) chip[DIS]: CHIP minimal mDNS started advertising.
I (96460) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=2156/08 cm=1 cp=0
I (96460) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: F04DD5D1FE008C38.
I (96480) chip[DIS]: mDNS service published: _matterc._udp
I (96480) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 7
I (96510) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0
I (96510) chip[DL]: CHIPoBLE unsubscribe received
I (96510) chip[DL]: BLE GAP connection terminated (con 0 reason 0x213)
I (96520) chip[TS]: Pending Last Known Good Time: 2025-01-03T14:59:09
I (96520) chip[TS]: Previous Last Known Good Time: 2025-01-03T14:55:54
I (96530) chip[TS]: Reverted Last Known Good Time to previous value
E (96540) chip[FP]: Warning: metadata not found during delete of fabric 0x2
E (96540) chip[ZCL]: OpCreds: failed to delete fabric at index 2: d8
I (96550) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 8 **********
I (96560) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 **********
I (96570) app_main: Commissioning failed, fail safe timer expired
I (96580) chip[FS]: Fail-safe cleanly disarmed
I (96580) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (96590) NimBLE: GAP procedure initiated: advertise;
I (96590) NimBLE: disc_mode=2
I (96600) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (96600) NimBLE:

I (96610) chip[DL]: CHIPoBLE advertising started
I (96610) app_main: Fabric removed successfully
I (96620) esp_matter_core: BLE Disconnected
I (96620) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (96630) chip[DL]: Device already advertising, stop active advertisement and restart
I (96630) NimBLE: GAP procedure initiated: stop advertising.

I (96640) NimBLE: GAP procedure initiated: advertise;
I (96640) NimBLE: disc_mode=2
I (96650) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (96660) NimBLE:

I (100590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (100590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
I (105590) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is -4500 **********
I (105590) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000405's Attribute 0x00000000 is 0 **********
@github-actions github-actions bot changed the title Commissioning device with qr code fails Commissioning device with qr code fails (CON-1494) Jan 3, 2025
@shubhamdp
Copy link
Contributor

Can you please share the details about the commissioner app, hub, commissioner side logs, to get an idea where it failed.

After AddNOC step I see the fail safe timer is set to 0 by the commissioner, instead it should have started the discovery of the device on the mdns.

@herculesp17
Copy link
Author

I tried commissioning the device with the chip tool and found out what was wrong.
The solution is in this topic #514

It might be useful to update the README.md here, so that it is clear what the parameters are for generating a factory partition. I could help with that, if needed. The information could be added in the Configure you app section.

@shubhamdp
Copy link
Contributor

@herculesp17 If you can, please raise the pull request with your suggestions.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants