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.

Sign up for GitHub

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

Jump to bottom

[ESP32C3] cannot finish commissioning #20537

Closed
mmt-10 opened this issue Jul 11, 2022 · 2 comments
Closed

[ESP32C3] cannot finish commissioning #20537

mmt-10 opened this issue Jul 11, 2022 · 2 comments

Comments

@mmt-10
Copy link

mmt-10 commented Jul 11, 2022 •
edited
Loading

Problem

  • expected behavior

  • actual behavior
    I set up and follow sequence about all-clusters-app
    Run chip-tool but chip-tool was stopped by timeout.
    How do I complete commissioning?
    If I need to modify menuconfig, please let me know setting on menuconfig.

  • steps to reproduce

  • system configuration

example : all-clusters-app.
ESP32 : ESP32-C3 (ESP32-C3-DevkitM-1)
I did not set RPC console.

connectedhomeip : master

$ git log -1
commit 776c06d (HEAD -> master, origin/master, origin/HEAD)
Author: Shubham Patil [email protected]
Date: Sat Jul 9 18:23:18 2022 +0530

[ESP32] Support flash encryption and nvs encryption (#20414)

- Added an option to encrypt the factory partition.
- Securely initialize the NVS partition if NVS encryption is enabled
- Added user guide for flash encryption in lighting-app/esp32

ESP-IDF : v4.4.1

$ git log -1
commit 1329b19fe494500aeb79d19b27cfd99b40c37aec (HEAD, tag: v4.4.1)
Author: Michael (XIAO Xufeng) [email protected]
Date: Sat Apr 16 09:43:14 2022 +0800

versions: Update version to 4.4.1

  • screenshots, images, logs, etc.

  • chip-tool log
    I set $SSID and $PASSWORD are WiFi AP at my home.

$ ./out/debug/chip-tool pairing ble-wifi 12344321 $SSID $PASSWORD 20202021 3840
[1657520561.895036][21740:21740] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1657520561.895478][21740:21740] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1657520561.895627][21740:21740] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1657520561.895737][21740:21740] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1657520561.896225][21740:21740] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-se6Q34)
[1657520561.896933][21740:21740] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657520561.897038][21740:21740] CHIP:DL: NVS set: chip-counters/reboot-count = 7 (0x7)
[1657520561.897595][21740:21740] CHIP:DL: Failed to get Ethernet interface
[1657520561.897961][21740:21740] CHIP:DL: Failed to reset Ethernet statistic counts
[1657520561.898143][21740:21740] CHIP:DL: Got WiFi interface: wlp1s0
[1657520561.899441][21740:21740] CHIP:DL: Found the primary WiFi interface:wlp1s0
[1657520561.899574][21740:21740] CHIP:IN: UDP::Init bind&listen port=0
[1657520561.899693][21740:21740] CHIP:IN: UDP::Init bound to port=52158
[1657520561.899739][21740:21740] CHIP:IN: UDP::Init bind&listen port=0
[1657520561.899823][21740:21740] CHIP:IN: UDP::Init bound to port=56227
[1657520561.899868][21740:21740] CHIP:IN: BLEBase::Init - setting/overriding transport
[1657520561.899909][21740:21740] CHIP:IN: TransportMgr initialized
[1657520561.899966][21740:21740] CHIP:FP: Initializing FabricTable from persistent storage
[1657520561.900239][21740:21740] CHIP:TS: Last Known Good Time: 2022-07-11T15:15:36
[1657520561.901082][21740:21740] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC514CBA34B4E423E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657520561.901678][21740:21740] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xE9F8A4A0812BB2F3, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657520561.902353][21740:21740] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x8EB7D3E2000C9D1D, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657520561.905426][21740:21740] CHIP:ZCL: Using ZAP configuration...
[1657520561.906207][21740:21740] CHIP:CTL: System State Initialized...
[1657520561.906304][21740:21740] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657520561.906352][21740:21740] CHIP:CTL: Setting attestation nonce to random value
[1657520561.906410][21740:21740] CHIP:CTL: Setting CSR nonce to random value
[1657520561.906487][21740:21740] CHIP:IN: UDP::Init bind&listen port=5550
[1657520561.906556][21740:21740] CHIP:IN: UDP::Init bound to port=5550
[1657520561.906597][21740:21740] CHIP:IN: UDP::Init bind&listen port=5550
[1657520561.906658][21740:21740] CHIP:IN: UDP::Init bound to port=5550
[1657520561.906695][21740:21740] CHIP:IN: TransportMgr initialized
[1657520561.906787][21740:21740] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657520561.906830][21740:21740] CHIP:CTL: Setting attestation nonce to random value
[1657520561.906877][21740:21740] CHIP:CTL: Setting CSR nonce to random value
[1657520561.910132][21740:21740] CHIP:CTL: Generating NOC
[1657520561.911567][21740:21740] CHIP:FP: Validating NOC chain
[1657520561.913924][21740:21740] CHIP:FP: NOC chain validation successful
[1657520561.914161][21740:21740] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1657520561.914211][21740:21740] CHIP:TS: Last Known Good Time: 2022-07-11T15:15:36
[1657520561.914249][21740:21740] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657520561.914282][21740:21740] CHIP:TS: Retaining current Last Known Good Time
[1657520561.917263][21740:21740] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1657520561.920055][21740:21740] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-11T15:15:36
[1657520561.922726][21740:21740] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1657520561.922806][21740:21740] CHIP:IN: UDP::Init bind&listen port=5550
[1657520561.922899][21740:21740] CHIP:IN: UDP::Init bound to port=5550
[1657520561.922940][21740:21740] CHIP:IN: UDP::Init bind&listen port=5550
[1657520561.923005][21740:21740] CHIP:IN: UDP::Init bound to port=5550
[1657520561.923044][21740:21740] CHIP:IN: TransportMgr initialized
[1657520561.923169][21740:21740] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657520561.923219][21740:21740] CHIP:CTL: Setting attestation nonce to random value
[1657520561.923281][21740:21740] CHIP:CTL: Setting CSR nonce to random value
[1657520561.924325][21740:21740] CHIP:CTL: Generating NOC
[1657520561.925615][21740:21740] CHIP:FP: Validating NOC chain
[1657520561.927975][21740:21740] CHIP:FP: NOC chain validation successful
[1657520561.928221][21740:21740] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669
[1657520561.928270][21740:21740] CHIP:TS: Last Known Good Time: 2022-07-11T15:15:36
[1657520561.928308][21740:21740] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657520561.928340][21740:21740] CHIP:TS: Retaining current Last Known Good Time
[1657520561.931214][21740:21740] CHIP:FP: Metadata for Fabric 0x2 persisted to storage.
[1657520561.933879][21740:21740] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-11T15:15:36
[1657520561.936400][21740:21740] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000
[1657520561.936477][21740:21740] CHIP:IN: UDP::Init bind&listen port=5550
[1657520561.936571][21740:21740] CHIP:IN: UDP::Init bound to port=5550
[1657520561.936614][21740:21740] CHIP:IN: UDP::Init bind&listen port=5550
[1657520561.936688][21740:21740] CHIP:IN: UDP::Init bound to port=5550
[1657520561.936707][21740:21740] CHIP:IN: TransportMgr initialized
[1657520561.936834][21740:21740] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657520561.936888][21740:21740] CHIP:CTL: Setting attestation nonce to random value
[1657520561.936949][21740:21740] CHIP:CTL: Setting CSR nonce to random value
[1657520561.938088][21740:21740] CHIP:CTL: Generating NOC
[1657520561.939379][21740:21740] CHIP:FP: Validating NOC chain
[1657520561.941697][21740:21740] CHIP:FP: NOC chain validation successful
[1657520561.941966][21740:21740] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669
[1657520561.942018][21740:21740] CHIP:TS: Last Known Good Time: 2022-07-11T15:15:36
[1657520561.942056][21740:21740] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657520561.942089][21740:21740] CHIP:TS: Retaining current Last Known Good Time
[1657520561.945048][21740:21740] CHIP:FP: Metadata for Fabric 0x3 persisted to storage.
[1657520561.947797][21740:21740] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-11T15:15:36
[1657520561.950418][21740:21740] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000
[1657520561.950500][21740:21740] CHIP:IN: UDP::Init bind&listen port=5550
[1657520561.950595][21740:21740] CHIP:IN: UDP::Init bound to port=5550
[1657520561.950636][21740:21740] CHIP:IN: UDP::Init bind&listen port=5550
[1657520561.950703][21740:21740] CHIP:IN: UDP::Init bound to port=5550
[1657520561.950746][21740:21740] CHIP:IN: TransportMgr initialized
[1657520561.988974][21740:21745] CHIP:DL: CHIP task running
[1657520561.989384][21740:21745] CHIP:IN: SecureSession[0x7f8844001a30]: Allocated Type:1 LSID:6378
[1657520561.989425][21740:21745] CHIP:SC: Assigned local session key ID 6378
[1657520561.989469][21740:21745] CHIP:SC: Including MRP parameters in PBKDF param request
[1657520561.989526][21740:21745] CHIP:IN: Prepared unauthenticated message 0x7f885a0b53f0 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 37515i with MessageCounter:204868355.
[1657520561.989567][21740:21745] CHIP:IN: Sending unauthenticated msg 0x7f885a0b53f0 with MessageCounter:204868355 to 0x0000000000000000 at monotonic time: 00000000007432E3 msec
[1657520561.989596][21740:21745] CHIP:IN: Message appended to BLE send queue
[1657520561.989613][21740:21745] CHIP:SC: Sent PBKDF param request
[1657520561.989632][21740:21745] CHIP:CTL: Setting wifi credentials from parameters
[1657520561.989647][21740:21745] CHIP:CTL: Setting attestation nonce to random value
[1657520561.989670][21740:21745] CHIP:CTL: Setting CSR nonce to random value
[1657520561.989698][21740:21745] CHIP:CTL: Commission called for node ID 0x0000000000BC5C01
[1657520561.989990][21740:21746] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1657520561.990155][21740:21743] CHIP:DL: TRACE: Bus acquired for name C-54ec
[1657520562.000269][21740:21745] CHIP:DL: PlatformBlueZInit init success
[1657520562.029835][21740:21743] CHIP:BLE: BLE removing known devices.
[1657520562.038510][21740:21743] CHIP:BLE: BLE initiating scan.
[1657520562.910776][21740:21745] CHIP:DL: Long dispatch time: 921 ms, for event type 2
[1657520562.915973][21740:21743] CHIP:BLE: New device scanned: FC:A3:BB:37:11:FC
[1657520562.916253][21740:21743] CHIP:BLE: Device discriminator match. Attempting to connect.
[1657520562.926758][21740:21743] CHIP:BLE: Scan complete notification without an active scan.
[1657520563.055751][21740:21743] CHIP:DL: ConnectDevice complete
[1657520572.921398][21740:21745] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1657520572.921464][21740:21745] CHIP:IN: Clearing BLE pending packets.
[1657520572.921495][21740:21745] CHIP:IN: BleConnection Error: ../../third_party/connectedhomeip/src/platform/Linux/BLEManagerImpl.cpp:63: CHIP Error 0x00000032: Timeout
[1657520592.006425][21740:21745] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
[1657520592.006505][21740:21745] CHIP:IN: SecureSession[0x7f8844001a30]: Released - Type:1 LSID:6378
[1657520592.006536][21740:21745] CHIP:TOO: Secure Pairing Failed
[1657520592.006614][21740:21745] CHIP:DIS: Closing all BLE connections
[1657520592.006659][21740:21745] CHIP:TOO: Pairing Failure: ../../third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:244: CHIP Error 0x00000032: Timeout
[1657520592.006975][21740:21740] CHIP:CTL: Shutting down the commissioner
[1657520592.007074][21740:21740] CHIP:CTL: Shutting down the controller
[1657520592.007102][21740:21740] CHIP:CTL: Shutting down the commissioner
[1657520592.007156][21740:21740] CHIP:CTL: Shutting down the controller
[1657520592.007175][21740:21740] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1657520592.007189][21740:21740] CHIP:FP: Forgetting fabric 0x1
[1657520592.007215][21740:21740] CHIP:TS: Pending Last Known Good Time: 2022-07-11T15:15:36
[1657520592.007451][21740:21740] CHIP:TS: Previous Last Known Good Time: 2022-07-11T15:15:36
[1657520592.007470][21740:21740] CHIP:TS: Reverted Last Known Good Time to previous value
[1657520592.007507][21740:21740] CHIP:CTL: Shutting down the commissioner
[1657520592.007560][21740:21740] CHIP:CTL: Shutting down the controller
[1657520592.007577][21740:21740] CHIP:IN: Expiring all sessions for fabric 0x2!!
[1657520592.007589][21740:21740] CHIP:FP: Forgetting fabric 0x2
[1657520592.007605][21740:21740] CHIP:TS: Pending Last Known Good Time: 2022-07-11T15:15:36
[1657520592.007774][21740:21740] CHIP:TS: Previous Last Known Good Time: 2022-07-11T15:15:36
[1657520592.007791][21740:21740] CHIP:TS: Reverted Last Known Good Time to previous value
[1657520592.007820][21740:21740] CHIP:CTL: Shutting down the commissioner
[1657520592.007871][21740:21740] CHIP:CTL: Shutting down the controller
[1657520592.007888][21740:21740] CHIP:IN: Expiring all sessions for fabric 0x3!!
[1657520592.007899][21740:21740] CHIP:FP: Forgetting fabric 0x3
[1657520592.007916][21740:21740] CHIP:TS: Pending Last Known Good Time: 2022-07-11T15:15:36
[1657520592.008080][21740:21740] CHIP:TS: Previous Last Known Good Time: 2022-07-11T15:15:36
[1657520592.008097][21740:21740] CHIP:TS: Reverted Last Known Good Time to previous value
[1657520592.008121][21740:21740] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1657520592.008232][21740:21740] CHIP:DMG: IM WH moving to [Uninitialized]
[1657520592.008251][21740:21740] CHIP:DMG: IM WH moving to [Uninitialized]
[1657520592.008261][21740:21740] CHIP:DMG: IM WH moving to [Uninitialized]
[1657520592.008271][21740:21740] CHIP:DMG: IM WH moving to [Uninitialized]
[1657520592.008283][21740:21740] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1657520592.008337][21740:21740] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1657520592.008824][21740:21740] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-wZDd72)
[1657520592.009861][21740:21740] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657520592.009995][21740:21740] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657520592.010051][21740:21740] CHIP:DL: Inet Layer shutdown
[1657520592.010106][21740:21740] CHIP:DL: BLE shutdown
[1657520592.011127][21740:21740] CHIP:DL: System Layer shutdown
[1657520592.011321][21740:21740] CHIP:TOO: Run command failure: ../../third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:244: CHIP Error 0x00000032: Timeout

  • ESP32-C3 log

ESP-ROM:esp32c3-api1-20210207
Build:Feb 7 2021
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd6100,len:0x16b4
load:0x403ce000,len:0x930
load:0x403d0000,len:0x2d28
entry 0x403ce000
I (30) boot: ESP-IDF v4.4.1 2nd stage bootloader
I (30) boot: compile time 14:24:09
I (30) boot: chip revision: 3
I (32) boot.esp32c3: SPI Speed : 80MHz
I (37) boot.esp32c3: SPI Mode : DIO
I (41) boot.esp32c3: SPI Flash Size : 4MB
I (46) boot: Enabling RNG early entropy source...
I (52) boot: Partition Table:
I (55) boot: ## Label Usage Type ST Offset Length
I (62) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (70) boot: 1 otadata OTA data 01 00 0000f000 00002000
I (77) boot: 2 phy_init RF data 01 01 0001100 00001000
I (85) boot: 3 ota_0 OTA app 00 10 00020000 00177000
I (92) boot: 4 ota_1 OTA app 00 11 001a0000 00177000
I (100) boot: 5 ot_storage Unknown data 01 3a 00317000 00002000
I (107) boot: End of partition table
I (112) esp_image: segment 0: paddr=00020020 vaddr=3c100020 size=355c8h (218568) map
I (154) esp_image: segment 1: paddr=000555f0 vaddr=3fc8f600 size=03908h ( 14600) load
I (157) esp_image: segment 2: paddr=00058f00 vaddr=40380000 size=07118h ( 28952) load
I (165) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=f9034h (1019956) map
I (328) esp_image: segment 4: paddr=0015905c vaddr=40387118 size=084a0h ( 33952) load
I (334) esp_image: segment 5: paddr=00161504 vaddr=50000010 size=00010h ( 16) load
I (340) boot: Loaded app from partition at offset 0x20000
I (340) boot: Disabling RNG early entropy source...
I (357) cpu_start: Pro cpu up.
I (365) cpu_start: Pro cpu start user code
I (365) cpu_start: cpu freq: 160000000
I (365) cpu_start: Application information:
I (368) cpu_start: Project name: chip-all-clusters-app
I (374) cpu_start: App version: TE9-1110-g776c06d5b-dirty
I (381) cpu_start: Compile time: Jul 11 2022 14:23:44
I (387) cpu_start: ELF file SHA256: 8210111848284e5b...
I (393) cpu_start: ESP-IDF: v4.4.1
I (398) heap_init: Initializing. RAM available for dynamic allocation:
I (405) heap_init: At 3FCA40D0 len 0001BF30 (111 KiB): DRAM
I (411) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM
I (418) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM
I (425) spi_flash: detected chip: generic
I (429) spi_flash: flash io: dio
I (434) sleep: Configure to isolate all GPIO pins in sleep state
I (440) sleep: Enable automatic switching of GPIO sleep configuration
I (447) coexist: coexist rom version 9387209
I (452) cpu_start: Starting scheduler.
I (462) all-clusters-app: ==================================================
I (462) all-clusters-app: chip-esp32-all-cluster-demo starting
I (472) all-clusters-app: ==================================================
I (482) pp: pp rom version: 9387209
I (482) net80211: net80211 rom version: 9387209
I (502) wifi:wifi driver task: 3fcad210, prio:23, stack:6656, core=0
I (502) system_api: Base MAC address is not set
I (502) system_api: read default base MAC address from EFUSE
I (512) wifi:wifi firmware version: 63017e0
I (512) wifi:wifi certification version: v7.0
I (512) wifi:config NVS flash: enabled
I (522) wifi:config nano formating: disabled
I (522) wifi:Init data frame dynamic rx buffer num: 32
I (522) wifi:Init management frame dynamic rx buffer num: 32
I (532) wifi:Init management short buffer num: 32
I (532) wifi:Init dynamic tx buffer num: 32
I (542) wifi:Init static tx FG buffer num: 2
I (542) wifi:Init static rx buffer size: 1600
I (552) wifi:Init static rx buffer num: 10
I (552) wifi:Init dynamic rx buffer num: 32
I (552) wifi_init: rx ba win: 6
I (562) wifi_init: tcpip mbox: 32
I (562) wifi_init: udp mbox: 6
I (572) wifi_init: tcp mbox: 6
I (572) wifi_init: tcp tx win: 5744
I (572) wifi_init: tcp rx win: 5744
I (582) wifi_init: tcp mss: 1440
I (582) wifi_init: WiFi IRAM OP enabled
I (592) wifi_init: WiFi RX IRAM OP enabled
I (602) chip[DL]: NVS set: chip-counters/reboot-count = 7 (0x7)
I (602) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (612) all-clusters-app: ------------------------Starting App Task---------------------------
W (612) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK
I (622) BTDM_INIT: BT controller compile version [d913766]
I (632) phy_init: phy_version 909,156dee4,Apr 7 2022,20:27:09
I (622) app-task: This is ESP32 chip with 1 CPU cores, WiFi/BLE,
I (642) app-task: silicon revision 3,
I (662) app-task: 4MB external flash

I (662) chip[SVR]: SetupQRCode: [MT:Y.K9042C00KA0648G00]
I (662) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code:
I (662) chip[SVR]: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I (682) chip[SVR]: Manual pairing code: [34970112332]
I (682) app-task: App Task started
I (772) BTDM_INIT: Bluetooth MAC: 84:f7:03:60:fb:e6

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

I (782) CHIP[DL]: BLE host-controller synced
I (1282) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (1282) NimBLE: GAP procedure initiated: advertise;
I (1282) NimBLE: disc_mode=2
I (1282) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1292) NimBLE:

I (1302) chip[DL]: CHIPoBLE advertising started
E (1302) chip[DL]: Long dispatch time: 689 ms, for event type 2
I (1312) chip[DL]: Starting ESP WiFi layer
I (1322) wifi:mode : sta (84:f7:03:60:fb:e4)
I (1322) wifi:enable tsf
W (1322) wifi:Haven't to connect to a suitable AP now!
I (1332) chip[DL]: Done driving station state, nothing else to do...
I (1332) phy: chan:1,max_power:80
I (1342) phy: chan:2,max_power:80
I (1342) phy: chan:3,max_power:80
I (1342) phy: chan:4,max_power:80
I (1352) phy: chan:5,max_power:80
I (1352) phy: chan:6,max_power:80
I (1362) phy: chan:7,max_power:80
I (1362) phy: chan:8,max_power:80
I (1362) phy: chan:9,max_power:80
I (1372) phy: chan:10,max_power:80
I (1372) phy: chan:11,max_power:80
I (1382) phy: chan:12,max_power:80
I (1382) phy: chan:13,max_power:80
I (1382) phy: chan:14,max_power:80
W (1392) wifi:Haven't to connect to a suitable AP now!
I (1392) chip[DL]: Done driving station state, nothing else to do...
I (1402) phy: chan:1,max_power:80
I (1402) phy: chan:2,max_power:80
I (1412) phy: chan:3,max_power:80
I (1412) phy: chan:4,max_power:80
I (1422) phy: chan:5,max_power:80
I (1422) phy: chan:6,max_power:80
I (1422) phy: chan:7,max_power:80
I (1432) phy: chan:8,max_power:80
I (1432) phy: chan:9,max_power:80
I (1442) phy: chan:10,max_power:80
I (1442) phy: chan:11,max_power:80
I (1442) phy: chan:12,max_power:80
I (1452) phy: chan:13,max_power:80
I (1452) phy: chan:14,max_power:80
I (1462) chip[SVR]: Server initializing...
I (1462) chip[TS]: Last Known Good Time: 2022-07-11T14:45:24
I (1472) chip[DMG]: AccessControl: initializing
I (1472) chip[DMG]: Examples::AccessControlDelegate::Init
I (1482) chip[DMG]: AccessControl: setting
I (1482) chip[DMG]: DefaultAclStorage: initializing
I (1492) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1512) chip[ZCL]: Using ZAP configuration...
I (1522) chip[DMG]: AccessControlCluster: initializing
I (1522) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (1532) app-devicecallbacks: Unhandled cluster ID: 48
I (1542) app-devicecallbacks: Current free heap: 125136

I (1542) chip[ZCL]: Initiating Admin Commissioning cluster.
I (1552) chip[ZCL]: Door Lock server initialized
I (1552) chip[ZCL]: Initialize PCC Plugin Server Cluster.
I (1562) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (1572) app-devicecallbacks: Current free heap: 125100

I (1582) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (1592) app-devicecallbacks: Unhandled cluster ID: 4
I (1592) app-devicecallbacks: Current free heap: 125100

I (1602) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0xfffc'
I (1612) app-devicecallbacks: Unhandled cluster ID: 4
I (1622) app-devicecallbacks: Current free heap: 125100

I (1632) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x002b', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (1642) app-devicecallbacks: Unhandled cluster ID: 43
I (1642) app-devicecallbacks: Current free heap: 125100

I (1652) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (1662) app-devicecallbacks: Current free heap: 125100

I (1672) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (1682) app-devicecallbacks: Unhandled cluster ID: 4
I (1682) app-devicecallbacks: Current free heap: 125100

I (1692) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0xfffc'
I (1702) app-devicecallbacks: Unhandled cluster ID: 4
I (1712) app-devicecallbacks: Current free heap: 125100

I (1712) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (1732) app-devicecallbacks: Unhandled cluster ID: 5
I (1732) app-devicecallbacks: Current free heap: 125100

I (1742) chip[ZCL]: On/Off set value: 1 0
I (1742) chip[ZCL]: On/off already set to new value
I (1752) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (1762) app-devicecallbacks: Current free heap: 125100

I (1772) chip[ZCL]: Window Covering Cluster init
I (1772) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (1782) app-devicecallbacks: Unhandled cluster ID: 258
I (1792) app-devicecallbacks: Current free heap: 125100

I (1802) chip[ZCL]: WC POST ATTRIBUTE=7
I (1802) chip[ZCL]: ConfigStatus 0x1B Operational=1 OnlineReserved=1
I (1812) chip[ZCL]: Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0)
I (1812) chip[ZCL]: Initialize PCC Server Cluster [EP:1]
I (1822) chip[ZCL]: Constant Pressure Supported
I (1832) chip[ZCL]: PCC Server: Constant Proportional Pressure Supported
I (1832) chip[ZCL]: PCC Server: Constant Flow Supported
I (1842) chip[ZCL]: PCC Server: Constant Temperature Supported
I (1852) chip[ZCL]: PCC Server: Constant Speed Supported
I (1852) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (1862) app-devicecallbacks: Unhandled AttributeId ID: '0x0007
I (1872) app-devicecallbacks: Current free heap: 125100

I (1882) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008'
I (1892) app-devicecallbacks: Unhandled AttributeId ID: '0x0008
I (1892) app-devicecallbacks: Current free heap: 125100

I (1902) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (1912) app-devicecallbacks: Unhandled AttributeId ID: '0x4001
I (1922) app-devicecallbacks: Current free heap: 125100

I (1932) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (1942) app-devicecallbacks: Unhandled cluster ID: 1030
I (1942) app-devicecallbacks: Current free heap: 125100

I (1952) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (1962) app-devicecallbacks: Unhandled cluster ID: 1030
I (1972) app-devicecallbacks: Current free heap: 125100

I (1972) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (1992) app-devicecallbacks: Unhandled cluster ID: 4
I (1992) app-devicecallbacks: Current free heap: 125100

I (2002) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0xfffc'
I (2012) app-devicecallbacks: Unhandled cluster ID: 4
I (2012) app-devicecallbacks: Current free heap: 125100

I (2022) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001'
I (2032) app-devicecallbacks: Unhandled cluster ID: 1030
I (2042) app-devicecallbacks: Current free heap: 125100

I (2042) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002'
I (2062) app-devicecallbacks: Unhandled cluster ID: 1030
I (2062) app-devicecallbacks: Current free heap: 125100

I (2072) chip[DIS]: Updating services using commissioning mode 1
I (2082) chip[DIS]: CHIP minimal mDNS started advertising.
I (2082) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15
I (2092) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (2102) chip[DIS]: mDNS service published: _matterc._udp
I (2112) chip[IN]: CASE Server enabling CASE session setups
I (2112) chip[SVR]: Joining Multicast groups
I (2122) chip[SVR]: Server Listening...
E (2122) chip[DL]: Long dispatch time: 665 ms, for event type 2
I (2132) app-devicecallbacks: Current free heap: 124376

I (2132) chip[DL]: WIFI_EVENT_STA_START
I (2142) phy: chan:1,max_power:80
I (2142) phy: chan:2,max_power:80
I (2152) phy: chan:3,max_power:80
I (2152) phy: chan:4,max_power:80
I (2152) phy: chan:5,max_power:80
I (2162) phy: chan:6,max_power:80
I (2162) phy: chan:7,max_power:80
I (2172) phy: chan:8,max_power:80
I (2172) phy: chan:9,max_power:80
I (2172) phy: chan:10,max_power:80
I (2182) phy: chan:11,max_power:80
I (2182) phy: chan:12,max_power:80
I (2192) phy: chan:13,max_power:80
I (2192) phy: chan:14,max_power:80
W (2202) wifi:Haven't to connect to a suitable AP now!
I (2202) chip[DL]: Done driving station state, nothing else to do...
I (2212) app-devicecallbacks: Current free heap: 124376

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

I (2242) NimBLE: GAP procedure initiated: advertise;
I (2242) NimBLE: disc_mode=2
I (2252) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2262) NimBLE:

I (2262) chip[SVR]: Cannot load binding table: a0
I (8232) chip[DL]: BLE GAP connection established (con 1)
I (8232) chip[DL]: CHIPoBLE advertising stopped
I (8232) app-devicecallbacks: Current free heap: 124384

I (40442) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213)
I (40452) app-devicecallbacks: CHIPoBLE disconnected
I (40452) app-devicecallbacks: Current free heap: 124384

I (40452) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840)
I (40462) NimBLE: GAP procedure initiated: advertise;
I (40472) NimBLE: disc_mode=2
I (40472) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (40482) NimBLE:

I (40492) chip[DL]: CHIPoBLE advertising started
I (40492) app-devicecallbacks: Current free heap: 124376
@sinny777
Copy link

I'm also facing the same problem....

@mmt-10
Copy link
Author

mmt-10 commented Jul 19, 2022

I solved this issue.

#20470 (comment)

#20470 (comment)

@mmt-10 mmt-10 closed this as completed Jul 19, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@sinny777 @mmt-10