Sproadic LoadProhibited (CON-907)

PhLuReh commented 11 months ago

Describe the bug While starting up, the FreeRTOS spradically get's killed by a LoadProhibited Exception. I already adressed this issue to the esp-idf, because I thought it may be idf related or even related to the linked issue. But they told me to report the error here.

Backtrace (full log attached below):

W (5047Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4009579a  PS      : 0x00060c33  A0      : 0x800941e1  A1      : 0x3fff3630
0x4009579a: uxListRemove at /opt/espressif/esp-idf/components/freertos/FreeRTOS-Kernel/list.c:195

A2      : 0x00000006  A3      : 0x00060c20  A4      : 0x00000000  A5      : 0x00060c23
A6      : 0xb33fffff  A7      : 0xb33fffff  A8      : 0x800950f0  A9      : 0x3fff3600
A10     : 0x00000001  A11     : 0x000000fe  A12     : 0x00000000  A13     : 0x00000000
A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x0000000a  EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000016  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff
0x4000c2e0: memcpy in ROM
0x4000c2f6: memcpy in ROM

Backtrace: 0x40095797:0x3fff3630 0x400941de:0x3fff3650 0x40154b39:0x3fff3670 0x40154b53:0x3fff3690 0x4013e20d:0x3fff36b0 0x40094fa6:0x3fff36d0
0x40095797: uxListRemove at /opt/espressif/esp-idf/components/freertos/FreeRTOS-Kernel/list.c:202
0x400941de: vTaskDelete at /opt/espressif/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:1434 (discriminator 4)
0x40154b39: esp_nimble_disable at /opt/espressif/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c:55
0x40154b53: nimble_port_freertos_deinit at /opt/espressif/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c:80
0x4013e20d: chip::DeviceLayer::Internal::BLEManagerImpl::bleprph_host_task(void*) at /home/smart/projects/smp_matter/build/esp-idf/chip/../../../../../../../opt/espressif/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:864
0x40094fa6: vPortTaskWrapper at /opt/espressif/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

Maybe this issue https://github.com/espressif/esp-matter/issues/722 is also related.

Environment

ESP-Matter Commit Id: d162b1357ce2d10a7971c434105633da0c4f3f11
ESP-IDF Commit Id: e088c3766ba440e72268b458a68f27b6e7d63986
SoC (eg: ESP32 or ESP32-C3): ESP32
Device Logs (Please attach the log file): new 9.txt
Host Machine OS: Linux version 6.1.29-1-MANJARO (builduser@fv-az292-908) (gcc (GCC) 12.2.1 20230201, GNU ld (GNU Binutils) 2.40) #1 SMP PREEMPT_DYNAMIC Wed May 17 14:00:55 UTC 2023
Commissioner app and versions if present:
Commissioner's logs if present:

Any additional details I modified my code to figure out what was the source of this exception. My list.c has this diff

diff --git a/components/freertos/FreeRTOS-Kernel/list.c b/components/freertos/FreeRTOS-Kernel/list.c
index dce9be1..081d6d6 100644
--- a/components/freertos/FreeRTOS-Kernel/list.c
+++ b/components/freertos/FreeRTOS-Kernel/list.c
@@ -194,6 +194,16 @@ UBaseType_t uxListRemove( ListItem_t * const pxItemToRemove )
  * item. */
     List_t * const pxList = pxItemToRemove->pxContainer;

+
+
+
+
+    if (pxItemToRemove == NULL) abort();
+    if (pxItemToRemove < (ListItem_t* const)0xff) abort();
+    if (pxItemToRemove->pxNext < (ListItem_t*)0xff) abort();
+    if (pxItemToRemove->pxPrevious < (ListItem_t*)0xff) abort();
+
+
     pxItemToRemove->pxNext->pxPrevious = pxItemToRemove->pxPrevious;
     pxItemToRemove->pxPrevious->pxNext = pxItemToRemove->pxNext;

I think it could be a race condition or some illegal memory access. As posted on the esp-idf repo i could drill it down to this location: if (pxItemToRemove < (ListItem_t* const)0xff) abort();

So I would assume, pxItemToRemove get's corrupted, is not NULL but according to the BT pxItemToRemove was 0x0000000a. Did not get any clue how up to now.

dhrishi commented 11 months ago

While starting up, the FreeRTOS spradically get's killed by a LoadProhibited Exception.

Does this happen everytime? With the default examples in esp-matter?

law-ko commented 11 months ago

I have this issue as well. With the default examples in esp-matter but with PSRAM enabled (NimBLE on top of PSRAM as well)

law-ko commented 11 months ago

Crash log:

I (3339) chip[ZCL]: Endpoint 2 On/off already set to new value
I (3339) esp_matter_core: Dynamic endpoint 2 added
I (3349) wifi:pm start, type: 1

I (3349) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (3389) esp_matter_core: BLE deinit successful and memory reclaimed
I (3389) chip[DL]: WIFI_EVENT_STA_START
I (3389) chip[DL]: Done driving station state, nothing else to do...
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4009498f  PS      : 0x00060a33  A0      : 0x802068c2  A1      : 0x3fff3e20  
0x4009498f: uxListRemove at /home/espuser/esp/esp-idf/components/freertos/FreeRTOS-Kernel/list.c:197

A2      : 0x00000006  A3      : 0x00060a20  A4      : 0x00000000  A5      : 0x00060a23  
A6      : 0xb33fffff  A7      : 0xb33fffff  A8      : 0x80094a5c  A9      : 0x3fff3df0  
A10     : 0x00000001  A11     : 0x00000000  A12     : 0xb33fffff  A13     : 0x00000000  
A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x0000000a  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0000000a  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
0x4000c2e0: memcpy in ROM

0x4000c2f6: memcpy in ROM

Backtrace: 0x4009498c:0x3fff3e20 0x402068bf:0x3fff3e40 0x4016d539:0x3fff3e60 0x4016d553:0x3fff3e80 0x401588d9:0x3fff3ea0 0x400949be:0x3fff3ec0
0x4009498c: uxListRemove at /home/espuser/esp/esp-idf/components/freertos/FreeRTOS-Kernel/list.c:192

0x402068bf: vTaskDelete at /home/espuser/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:1434 (discriminator 4)

0x4016d539: esp_nimble_disable at /home/espuser/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c:55

0x4016d553: nimble_port_freertos_deinit at /home/espuser/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c:80

0x401588d9: chip::DeviceLayer::Internal::BLEManagerImpl::bleprph_host_task(void*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:864

0x400949be: vPortTaskWrapper at /home/espuser/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

shubhamdp commented 10 months ago

@PhLuReh, @law-ko Can you please share the sdkconfig on which you are getting the crash, I'll try to reproduce for further debugging.

PhLuReh commented 10 months ago

Here my sdkconfig.zip Thank you for investigating!

MysteryMS commented 9 months ago

Any updates? I'm having this issue too. Sometimes after the first crash and reboot it goes back to normal, sometimes it takes minutes for it to actually boot (after many crashes).

law-ko commented 8 months ago

@shubhamdp It's been quite a while and this issue still exists at release/v1.2 branch, how can this be fixed? I am on ESP32-PICO-MINI-02

znicky commented 8 months ago

I'm having this issue. How can this be fixed?

PhLuReh commented 8 months ago

As I opened this issue and am currently not suffering from this issue, I think it was very likely caused by a memory leak/misuse in the main application. So I would say, the Kernel structures are likely to be damaged by the tasks.

Please be sure:

Do not share stack variables outside the stack/function hierarchy (local only stack access)
Do not free memory and let tasks still use it (maybe concurrent tasks).
Check you stack usage (this is normally detected)

law-ko commented 8 months ago

As I opened this issue and am currently not suffering from this issue, I think it was very likely caused by a memory leak/misuse in the main application. So I would say, the Kernel structures are likely to be damaged by the tasks.

Please be sure:

Do not share stack variables outside the stack/function hierarchy (local only stack access)

Do not free memory and let tasks still use it (maybe concurrent tasks).

Check you stack usage (this is normally detected)

I don't think this is true, as it also happens on a blank light project example.

shubhamdp commented 7 months ago

@PhLuReh @law-ko We've found the problem and we'll release the fix soon. Till then, can you please check with this patch if your crash disappears?

cd esp-matter
curl https://github.com/shubhamdp/esp-matter/commit/8e0aebf815d11f3c43132c3fa27f5da085f06d2c.patch | git am

Edit: This patch is on release/v1.2 branch

PhLuReh commented 7 months ago

I'm not able to test this, as I'm still tied to v1.1 due to my test lab, which has not shifted to v1.2 so far.

shubhamdp commented 7 months ago

@PhLuReh did you see this problem on v1.1 as well?

PhLuReh commented 7 months ago

As I wrote in https://github.com/espressif/esp-matter/issues/748#issuecomment-1999080764 - I saw it, that's why I raised this issue. But p to now, it did not come up again.

law-ko commented 7 months ago

@shubhamdp Tested and randomly got this error:

I (53022) chip[DL]: BLE GAP connection established (con 0)
I (53022) chip[DL]: CHIPoBLE advertising stopped
I (54382) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (54392) chip[BLE]: local and remote recv window sizes = 5
I (54392) chip[BLE]: selected BTP version 4
I (54402) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (56632) chip[DL]: BLE GAP connection terminated (con 0 reason 0x213)
E (56632) chip[DL]: Chip stack locking error at 'src/system/SystemLayerImplFreeRTOS.cpp:101'. Code is unsafe/racy
E (56642) chip[-]: chipDie chipDie chipDie

abort() was called at PC 0x4018d02b on core 0
0x4018d02b: chip::Platform::Internal::AssertChipStackLockedByCurrentThread(char const*, int) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/CodeUtils.h:492
 (inlined by) chipDie at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/CodeUtils.h:502
 (inlined by) chip::Platform::Internal::AssertChipStackLockedByCurrentThread(char const*, int) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/LockTracker.cpp:36

Backtrace: 0x40081c6e:0x3ffef8e0 0x40093fad:0x3ffef900 0x40098986:0x3ffef920 0x4018d02b:0x3ffef990 0x4018dc01:0x3ffef9b0 0x401aa7d1:0x3ffef9d0 0x401aaa84:0x3ffef9f0 0x40187409:0x3ffefa10 0x401990f3:0x3ffefa30 0x4019927d:0x3ffefa90 0x400fe481:0x3ffefab0 0x400fef31:0x3ffefad0 0x400fef58:0x3ffefb30 0x400fbbce:0x3ffefb90 0x400fbde3:0x3ffefbb0 0x400fb415:0x3ffefbd0 0x40092263:0x3ffefbf0 0x40084ded:0x3ffefc10 0x401989fa:0x3ffefc30 0x400944ae:0x3ffefc50
0x40081c6e: panic_abort at /Users/lawrenceko/esp/esp-idf/components/esp_system/panic.c:452
0x40093fad: esp_system_abort at /Users/lawrenceko/esp/esp-idf/components/esp_system/port/esp_system_chip.c:84
0x40098986: abort at /Users/lawrenceko/esp/esp-idf/components/newlib/abort.c:38
0x4018d02b: chip::Platform::Internal::AssertChipStackLockedByCurrentThread(char const*, int) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/CodeUtils.h:492
 (inlined by) chipDie at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/CodeUtils.h:502
 (inlined by) chip::Platform::Internal::AssertChipStackLockedByCurrentThread(char const*, int) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/LockTracker.cpp:36
0x4018dc01: chip::System::LayerImplFreeRTOS::CancelTimer(void (*)(chip::System::Layer*, void*), void*) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/system/SystemLayerImplFreeRTOS.cpp:101
0x401aa7d1: chip::Ble::BLEEndPoint::StopReceiveConnectionTimer() at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/ble/BLEEndPoint.cpp:1487
0x401aaa84: chip::Ble::BLEEndPoint::DoClose(unsigned char, chip::ChipError) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/ble/BLEEndPoint.cpp:331
0x40187409: chip::Ble::BleLayer::HandleConnectionError(unsigned short, chip::ChipError) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/ble/BleLayer.cpp:738
0x401990f3: chip::DeviceLayer::Internal::BLEManagerImpl::HandleGAPDisconnect(ble_gap_event*) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:1291
0x4019927d: chip::DeviceLayer::Internal::BLEManagerImpl::ble_svr_gap_event(ble_gap_event*, void*) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:1374
0x400fe481: ble_gap_call_event_cb at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:773
0x400fef31: ble_gap_conn_broken at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:1344
0x400fef58: ble_gap_rx_disconn_complete at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:1372 (discriminator 4)
0x400fbbce: ble_hs_hci_evt_disconn_complete at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci_evt.c:294
 (inlined by) ble_hs_hci_evt_disconn_complete at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci_evt.c:212
0x400fbde3: ble_hs_hci_evt_process at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci_evt.c:1051
0x400fb415: ble_hs_event_rx_hci_ev at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:526
0x40092263: npl_freertos_event_run at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/npl_os_freertos.c:451
0x40084ded: ble_npl_event_run at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:185
 (inlined by) nimble_port_run at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:248
0x401989fa: chip::DeviceLayer::Internal::BLEManagerImpl::bleprph_host_task(void*) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:863
0x400944ae: vPortTaskWrapper at /Users/lawrenceko/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

ELF file SHA256: 3d4acda66b003d23

Rebooting...
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 271414342, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:5820
ho 0 tail 12 room 4
load:0x40078000,len:15124
load:0x40080400,len:4
0x40080400: _init at ??:?

shubhamdp commented 7 months ago

@law-ko can you please share the esp-matter or connectedhomeip commit id? Also, please specify if you are using specific branch of esp-matter.

This crash is similar to https://github.com/project-chip/connectedhomeip/issues/28142 and was fixed in https://github.com/project-chip/connectedhomeip/pull/29180.

law-ko commented 7 months ago

@shubhamdp Upon further testing, the error still exists even after applying the patch:

E (3462) chip[DL]: Long dispatch time: 1287 ms, for event type 2
I (3462) chip[DL]: WIFI_EVENT_STA_START
I (3842) chip[DL]: Done driving station state, nothing else to do...
I (3842) NimBLE: GAP procedure initiated: stop advertising.

I (3852) wifi:state: auth -> assoc (0)
I (3852) chip[DL]: CHIPoBLE advertising stopped
I (3862) chip[IM]: No subscriptions to resume
I (3862) NimBLE: GAP procedure initiated: stop advertising.

I (3872) wifi:state: assoc -> run (10)
I (3882) esp_matter_core: BLE deinit successful and memory reclaimed
I (3882) app_main: BLE deinitialized and memory reclaimed
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4009447f  PS      : 0x00060533  A0      : 0x801dc0be  A1      : 0x3ffefd40  
0x4009447f: uxListRemove at /Users/lawrenceko/esp/esp-idf/components/freertos/FreeRTOS-Kernel/list.c:197

A2      : 0x00000006  A3      : 0x00060520  A4      : 0x00000000  A5      : 0x00060523  
A6      : 0xb33fffff  A7      : 0xb33fffff  A8      : 0x8009454c  A9      : 0x3ffefd10  
A10     : 0x00000001  A11     : 0x00000000  A12     : 0xb33fffff  A13     : 0x00000000  
A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x0000000a  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0000000a  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
0x4000c2e0: memcpy in ROM
0x4000c2f6: memcpy in ROM

Backtrace: 0x4009447c:0x3ffefd40 0x401dc0bb:0x3ffefd60 0x401af6bc:0x3ffefd80 0x401af6d7:0x3ffefda0 0x401989fd:0x3ffefdc0 0x400944ae:0x3ffefde0
0x4009447c: uxListRemove at /Users/lawrenceko/esp/esp-idf/components/freertos/FreeRTOS-Kernel/list.c:192
0x401dc0bb: vTaskDelete at /Users/lawrenceko/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:1434 (discriminator 4)
0x401af6bc: esp_nimble_disable at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c:55
0x401af6d7: nimble_port_freertos_deinit at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c:80
0x401989fd: chip::DeviceLayer::Internal::BLEManagerImpl::bleprph_host_task(void*) at /Users/lawrenceko/esp-git/esp-matter/examples/outlet/build/esp-idf/chip/../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:864
0x400944ae: vPortTaskWrapper at /Users/lawrenceko/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

Branch: release/v1.2

Does this patch need to be on the latest commit ID on the release/v1.2 branch?

shubhamdp commented 7 months ago

I did use the latest release/v1.2 for reproducing the crash, and fixing it. Please give a try there, its an intermittent crash (I guess).

If you can, please help test two more minor changes separately. These are workarounds I tried to figure out the root cause of crash.

Add some delay [vTaskDelay(1000 / portTICK_PERIOD_MS);] before nimble_port_deinit() https://github.com/espressif/esp-matter/blob/0e10da9cc529cddbface642e6bc9ee9f9007a547/components/esp_matter/esp_matter_core.cpp#L869-L874
And second one is in esp-idf, in file components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c, replace below 4 lines with vTaskDelete(NULL);
```
if (host_task_h) {
    vTaskDelete(host_task_h);
    host_task_h = NULL;
}
```

shubhamdp commented 7 months ago

@law-ko any updates here?

law-ko commented 6 months ago

I did use the latest release/v1.2 for reproducing the crash, and fixing it. Please give a try there, its an intermittent crash (I guess).

If you can, please help test two more minor changes separately. These are workarounds I tried to figure out the root cause of crash.

Add some delay [vTaskDelay(1000 / portTICK_PERIOD_MS);] before nimble_port_deinit() https://github.com/espressif/esp-matter/blob/0e10da9cc529cddbface642e6bc9ee9f9007a547/components/esp_matter/esp_matter_core.cpp#L869-L874

And second one is in esp-idf, in file components/bt/host/nimble/nimble/porting/npl/freertos/src/nimble_port_freertos.c, replace below 4 lines with vTaskDelete(NULL);
    if (host_task_h) {
        vTaskDelete(host_task_h);
        host_task_h = NULL;
    }

Testing with the first option adding delay with 1000 ms works now, will continue to observe as this is a intermittent crash.

shubhamdp commented 6 months ago

@law-ko I have put up some solid fix here, PTAL: https://github.com/project-chip/connectedhomeip/pull/33109 This will be adde to esp-matter shortly.

law-ko commented 6 months ago

@law-ko I have put up some solid fix here, PTAL: project-chip/connectedhomeip#33109 This will be adde to esp-matter shortly.

Does this mean the first option of adding 1000ms is not necessary?

shubhamdp commented 6 months ago

Yes, the above suggested work arounds won't be necessary, I'll post once we merge the changes

law-ko commented 6 months ago

@shubhamdp Is the merge completed yet?

shubhamdp commented 6 months ago

@law-ko it's merge in release/v1.2 branch https://github.com/espressif/esp-matter/commit/9fcfe90a9754fb046b75c82b0986afe33a52a93e, please give it a try

law-ko commented 6 months ago

@shubhamdp I don't think it is fixed, this is the crash log:

I (6534) chip[DL]: BLE deinit successful and memory reclaimed
I (6534) app_main: BLE is deinitialized
I (6884) ROUTE_HOOK: Received RIO
I (6884) ROUTE_HOOK: prefix FDC3:A10B:1B01:: lifetime 1800
I (7004) chip[EM]: >>> [E:47745r S:0 M:75508052] (U) Msg RX from 0:15AF3134864C568E [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (7004) chip[IN]: CASE Server received Sigma1 message . Starting handshake. EC 0x3ffcb2e8
I (7014) chip[EM]: <<< [E:47745r S:0 M:218885727 (Ack:75508052)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::1B:3D4A:14C9:5F76%st1]:57022] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (7034) chip[SC]: Received Sigma1 msg
I (7044) chip[EM]: <<< [E:47745r S:0 M:218885728 (Ack:75508052)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::1B:3D4A:14C9:5F76%st1]:57022] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
Total HEAP left: 1700116
HEAP in DRAM: 62963
HEAP in PSRAM: 1637176

I (7084) chip[EM]: >>> [E:47745r S:0 M:75508053 (Ack:218885728)] (U) Msg RX from 0:15AF3134864C568E [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (7094) chip[SC]: Success status report received. Session was established
Total HEAP left: 1681988
HEAP in DRAM: 62171
HEAP in PSRAM: 1619840

I (8144) chip[SC]: SecureSession[0x3ffc9ad0, LSID:29343]: State change 'kEstablishing' --> 'kActive'
I (8144) chip[IN]: CASE Session established to peer: <0000000027DB8A03, 1>
I (8154) chip[EM]: <<< [E:47745r S:0 M:218885729 (Ack:75508053)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::1B:3D4A:14C9:5F76%st1]:57022] --- Type 0000:10 (SecureChannel:StandaloneAck)
E (8164) chip[DL]: Long dispatch time: 1083 ms, for event type 3
I (8174) chip[EM]: >>> [E:47746r S:29343 M:32139792] (S) Msg RX from 1:0000000027DB8A03 [20D9] --- Type 0001:03 (IM:SubscribeRequest)
I (8194) chip[DMG]: Final negotiated min/max parameters: Min = 0s, Max = 60s
I (8214) chip[EM]: >>> [E:47745r S:0 M:75508053 (Ack:218885728)] (U) Msg RX from 0:15AF3134864C568E [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (8214) chip[EM]: <<< [E:47745r S:0 M:218885730 (Ack:75508053)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::1B:3D4A:14C9:5F76%st1]:57022] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (8234) chip[EM]: >>> [E:47746r S:29343 M:32139792] (S) Msg RX from 1:0000000027DB8A03 [20D9] --- Type 0001:03 (IM:SubscribeRequest)
I (8244) chip[EM]: <<< [E:47746r S:29343 M:26714622 (Ack:32139792)] (S) Msg TX to 1:0000000027DB8A03 [20D9] [UDP:[FE80::1B:3D4A:14C9:5F76%st1]:57022] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (8264) chip[DIS]: Node ID resolved for 3FC5D006233120D9:0000000027DB8A03
I (8274) chip[DIS]: UDP:[FDD5:B45E:4AC7:49:C2D:C4EE:CECD:6436%st1]:57022: new best score: 3
I (8274) chip[DIS]: UDP:[FDD5:B45E:4AC7:49:2:FDC3:A10B:1B01%st1]:57022: score has not improved: 3
I (8284) chip[DIS]: UDP:[FE80::1B:3D4A:14C9:5F76%st1]:57022: new best score: 7
I (8294) chip[DIS]: UDP:192.168.2.213%st1:57022: score has not improved: 2
I (8304) chip[DIS]: Checking node lookup status after 3762 ms
I (8304) chip[SC]: Initiating session on local FabricIndex 1 from 0x00000000883FB3A7 -> 0x0000000027DB8A03
I (8404) chip[EM]: <<< [E:64247i S:0 M:218885731] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::1B:3D4A:14C9:5F76%st1]:57022] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (8414) chip[SC]: Sent Sigma1 msg

assert failed: tlsf_free tlsf.c:1120 (!block_is_free(block) && "block already marked as free")
HINT: CORRUPT HEAP: heap metadata corrupted resulting in TLSF malfunction.
Make sure you are not making out of bound writing on the memory you allocate in your application.
Make sure you are not writing on freed memory.
For more information run 'idf.py docs -sp api-reference/system/heap_debug.html'.

Backtrace: 0x4008195a:0x3ffef420 0x4009391d:0x3ffef440 0x40098599:0x3ffef460 0x400964b4:0x3ffef580 0x4009633c:0x3ffef5a0 0x400822af:0x3ffef5c0 0x40082687:0x3ffef5e0 0x40082819:0x3ffef610 0x400e7590:0x3ffef630 0x400ece29:0x3ffef650 0x4014ebb6:0x3ffef670 0x4014ec29:0x3ffef690 0x4014f06b:0x3ffef6b0 0x40138889:0x3ffef700 0x40138bc2:0x3ffef720 0x40138bf5:0x3ffef790 0x40093cf6:0x3ffef7b0
0x4008195a: panic_abort at /Users/lawrenceko/esp/esp-idf/components/esp_system/panic.c:472
0x4009391d: esp_system_abort at /Users/lawrenceko/esp/esp-idf/components/esp_system/port/esp_system_chip.c:93
0x40098599: __assert_func at /Users/lawrenceko/esp/esp-idf/components/newlib/assert.c:81
0x400964b4: block_next at /Users/lawrenceko/esp/esp-idf/components/heap/tlsf/tlsf_block_functions.h:94 (discriminator 1)
 (inlined by) block_link_next at /Users/lawrenceko/esp/esp-idf/components/heap/tlsf/tlsf_block_functions.h:101 (discriminator 1)
 (inlined by) block_mark_as_free at /Users/lawrenceko/esp/esp-idf/components/heap/tlsf/tlsf_block_functions.h:109 (discriminator 1)
 (inlined by) tlsf_free at /Users/lawrenceko/esp/esp-idf/components/heap/tlsf/tlsf.c:1121 (discriminator 1)
0x4009633c: multi_heap_free_impl at /Users/lawrenceko/esp/esp-idf/components/heap/multi_heap.c:234
 (inlined by) multi_heap_free_impl at /Users/lawrenceko/esp/esp-idf/components/heap/multi_heap.c:223
0x400822af: heap_caps_free at /Users/lawrenceko/esp/esp-idf/components/heap/heap_caps.c:393
0x40082687: trace_free at /Users/lawrenceko/esp/esp-idf/components/heap/include/heap_trace.inc:141
0x40082819: __wrap_free at /Users/lawrenceko/esp/esp-idf/components/heap/include/heap_trace.inc:186
0x400e7590: _mdns_query_results_free at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/managed_components/espressif__mdns/mdns.c:6566
0x400ece29: mdns_query_results_free at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/managed_components/espressif__mdns/mdns.c:6539
0x4014ebb6: chip::Dnssd::ResolveContext::~ResolveContext() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/WiFiDnssdImpl.h:129
 (inlined by) void chip::Platform::Delete<chip::Dnssd::ResolveContext>(chip::Dnssd::ResolveContext*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/CHIPMem.h:168
 (inlined by) void chip::Platform::Delete<chip::Dnssd::ResolveContext>(chip::Dnssd::ResolveContext*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/CHIPMem.h:161
0x4014ec29: chip::Dnssd::RemoveMdnsQuery(chip::Dnssd::GenericContext*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/WiFiDnssdImpl.cpp:127
0x4014f06b: chip::Dnssd::MdnsQueryDone(int) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/WiFiDnssdImpl.cpp:478
 (inlined by) MdnsQueryDone at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/WiFiDnssdImpl.cpp:588
0x40138889: chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::_DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:290
0x40138bc2: chip::DeviceLayer::PlatformManager::DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:503
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:257
0x40138bf5: chip::DeviceLayer::PlatformManager::RunEventLoop() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:403
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::EventLoopTaskMain(void*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:280
0x40093cf6: vPortTaskWrapper at /Users/lawrenceko/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134

shubhamdp commented 6 months ago

@law-ko Thanks for trying it out, this is a fresh one and the one due to ble deinit race is fixed.

For this one, can you tell me please tell me the espressif/mdns version that you are using. Open up the dependencies.lock file in your project and find mdns and version.

If its 1.3.0 can you please change it to version: "1.2.5" in connectedhomeip/connectedhomeip/config/esp32/components/chip/idf_component.yml. (NOTE: Please make sure to remove that ~ from there, else it will pick the latest one i.e. 1.3.0)

law-ko commented 6 months ago

@law-ko Thanks for trying it out, this is a fresh one and the one due to ble deinit race is fixed.

For this one, can you tell me please tell me the espressif/mdns version that you are using. Open up the dependencies.lock file in your project and find mdns and version.

If its 1.3.0 can you please change it to version: "1.2.5" in connectedhomeip/connectedhomeip/config/esp32/components/chip/idf_component.yml. (NOTE: Please make sure to remove that ~ from there, else it will pick the latest one i.e. 1.3.0)

@shubhamdp The version I found in dependencies.lock is 1.3.0.

Under connectedhomeip/connectedhomeip/config/esp32/components/chip/idf_component.yml it is currently shown as ^1.1.0, I have changed it to 1.2.5.

Note this is an intermittent issue as well.

shubhamdp commented 6 months ago

Please let me know if this occurs on 1.2.5. Our team had identified the fixed and will be available in next mdns release.

law-ko commented 6 months ago

@shubhamdp I think this occurs after merging as well:

E (19621) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (19621) task_wdt:  - IDLE0 (CPU 0)
E (19621) task_wdt: Tasks currently running:
E (19621) task_wdt: CPU 0: CHIP
E (19621) task_wdt: CPU 1: IDLE1
E (19621) task_wdt: Print CPU 0 (current core) backtrace

Backtrace: 0x401B7F6F:0x3FFC00B0 0x4008F649:0x3FFC00E0 0x40008544:0x3FFEEB20 0x4014F962:0x3FFEEB40 0x40156CE5:0x3FFEEB60 0x40138990:0x3FFEEB80 0x4013899E:0x3FFEEBA0 0x401390EC:0x3FFEEBC0 0x401391E6:0x3FFEEC20 0x40137EF1:0x3FFEEC80 0x40137F39:0x3FFEECA0 0x40138266:0x3FFEECC0 0x40138299:0x3FFEED30 0x40093CC2:0x3FFEED50
0x401b7f6f: task_wdt_timeout_handling at /Users/lawrenceko/esp/esp-idf/components/esp_system/task_wdt/task_wdt.c:441
 (inlined by) task_wdt_isr at /Users/lawrenceko/esp/esp-idf/components/esp_system/task_wdt/task_wdt.c:515
0x4008f649: _xt_lowint1 at /Users/lawrenceko/esp/esp-idf/components/xtensa/xtensa_vectors.S:1240
0x40008544: ets_delay_us in ROM
0x4014f962: esp_bt_controller_disable at /Users/lawrenceko/esp/esp-idf/components/bt/controller/esp32/bt.c:1717
0x40156ce5: nimble_port_deinit at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:216
0x40138990: chip::DeviceLayer::Internal::BLEManagerImpl::DeinitBLE() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:995
0x4013899e: chip::DeviceLayer::Internal::BLEManagerImpl::DeinitESPBleLayer() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:953
0x401390ec: chip::DeviceLayer::Internal::BLEManagerImpl::DriveBLEState() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:824
0x401391e6: chip::DeviceLayer::Internal::BLEManagerImpl::_OnPlatformEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:391
0x40137ef1: chip::DeviceLayer::Internal::BLEManager::OnPlatformEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/BLEManager.h:163
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::DispatchEventToDeviceLayer(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:321
0x40137f39: chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::_DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:295 (discriminator 1)
0x40138266: chip::DeviceLayer::PlatformManager::DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:503
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:257
0x40138299: chip::DeviceLayer::PlatformManager::RunEventLoop() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:403
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::EventLoopTaskMain(void*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:280
0x40093cc2: vPortTaskWrapper at /Users/lawrenceko/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134

shubhamdp commented 6 months ago

@law-ko please share the sdkconfig, esp-idf and esp-matter commits. Do you have any patches on top of esp-matter, esp-idf? In which example this reproducible? Anything different that you are doing in your application?

Any more details that would help debug this issue.

As per time stamp it looks like its getting hit very late, around 20s after bootup, anything different going on before starting matter?

law-ko commented 6 months ago

@law-ko please share the sdkconfig, esp-idf and esp-matter commits. Do you have any patches on top of esp-matter, esp-idf? In which example this reproducible? Anything different that you are doing in your application?

Any more details that would help debug this issue.

As per time stamp it looks like its getting hit very late, around 20s after bootup, anything different going on before starting matter?

@shubhamdp The esp-matter commit is c5d583525116bea8ce97e3567bf6f4e18985a960 The esp-idf commit is a322e6bdad4b6675d4597fb2722eea2851ba88cb

We do not have additional patches on top of it, but we have other programs that we run in other tasks. We are using PSRAM as well.

This can occur once after the boot up, after Wi-Fi is connected. The timestamp late is due to copying the latter crash log.

law-ko commented 6 months ago

@shubhamdp

Keep in mind we are using ESP-PICO-MINI-02 with BLE on top of DRAM and Matter stack on top of PSRAM.

A full log from boot:

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 271414342, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:2, clock div:1
secure boot v2 enabled
secure boot verification succeeded
load:0x3fff00b8 len:0x2d30
load:0x40078000 len:0x5db4
load:0x40080400 len:0x4
0x40080400: _init at ??:?

load:0x40080404 len:0xdac
entry 0x400805e4
I (672) cpu_start: Multicore app
I (672) quad_psram: This chip is ESP32-PICO-V3-02
I (672) esp_psram: Found 2MB PSRAM device
I (674) esp_psram: Speed: 80MHz
I (678) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
I (928) esp_psram: SPI SRAM memory test OK
I (936) cpu_start: Pro cpu start user code
I (936) cpu_start: cpu freq: 160000000 Hz
I (936) cpu_start: Application information:
I (939) cpu_start: Project name:     outlet
I (944) cpu_start: App version:      0.4.2
I (948) cpu_start: Compile time:     May 16 2024 11:46:21
I (955) cpu_start: ELF file SHA256:  8badd05f9cb5a4cd...
I (961) cpu_start: ESP-IDF:          v5.2.1
I (965) cpu_start: Min chip rev:     v3.0
I (970) cpu_start: Max chip rev:     v3.99 
I (975) cpu_start: Chip rev:         v3.0
I (980) heap_init: Initializing. RAM available for dynamic allocation:
I (987) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (993) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (999) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1005) heap_init: At 3FFD8100 len 00007F00 (31 KiB): DRAM
I (1011) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1018) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1024) heap_init: At 4009E6C8 len 00001938 (6 KiB): IRAM
I (1031) esp_psram: Adding pool of 2048K of PSRAM memory to heap allocator
I (1039) spi_flash: detected chip: generic
I (1043) spi_flash: flash io: dio
W (1047) flash_encrypt: Flash encryption mode is DEVELOPMENT (not secure)
I (1056) nvs_sec_provider: NVS Encryption - Registering Flash encryption-based scheme...
I (1070) coexist: coex firmware version: 77cd7f8
I (1071) main_task: Started on CPU0
I (1081) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1081) main_task: Calling app_main()
I (1301) nvs: NVS partition "nvs" is encrypted.
W (1521) ledc: fade callback not in IRAM
I (1541) gpio: GPIO[25]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1571) gpio: GPIO[26]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1741) button: IoT Button Version: 3.1.3
I (1811) app_matter: Outlet one created with endpoint_id 1
I (1811) app_matter: Outlet two created with endpoint_id 2
hostname endpoint id: 0
I (1901) wifi:wifi driver task: 3ffdd864, prio:23, stack:6656, core=0
I (1921) wifi:wifi firmware version: a9f5b59
I (1921) wifi:wifi certification version: v7.0
I (1921) wifi:config NVS flash: enabled
I (1921) wifi:config nano formating: disabled
I (1931) wifi:Init data frame dynamic rx buffer num: 32
I (1931) wifi:Init static rx mgmt buffer num: 5
I (1941) wifi:Init management short buffer num: 32
I (1941) wifi:Init static tx buffer num: 16
I (1951) wifi:Init tx cache buffer num: 32
I (1951) wifi:Init static rx buffer size: 1600
I (1951) wifi:Init static rx buffer num: 10
I (1961) wifi:Init dynamic rx buffer num: 32
I (1961) wifi_init: rx ba win: 6
I (1961) wifi_init: tcpip mbox: 32
I (1971) wifi_init: udp mbox: 6
I (1971) wifi_init: tcp mbox: 6
I (1981) wifi_init: tcp tx win: 5744
I (1981) wifi_init: tcp rx win: 5744
I (1981) wifi_init: tcp mss: 1440
I (1991) wifi_init: WiFi/LWIP prefer SPIRAM
I (1991) wifi_init: WiFi IRAM OP enabled
I (2001) wifi_init: WiFi RX IRAM OP enabled
I (2101) chip[DL]: NVS set: chip-counters/reboot-count = 141 (0x8D)
I (2101) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (2111) BTDM_INIT: BT controller compile version [0f0c5a2]
I (2111) BTDM_INIT: Bluetooth MAC: 4c:75:25:f0:5d:06
I (2121) phy_init: phy_version 4791,2c4672b,Dec 20 2023,16:06:06
I (2461) CHIP[DL]: BLE host-controller synced
I (2971) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (2981) chip[DL]: CHIPoBLE advertising started
E (2981) chip[DL]: Long dispatch time: 873 ms, for event type 2
I (2981) chip[DL]: Starting ESP WiFi layer
I (2991) wifi:mode : sta (4c:75:25:f0:5d:04)
I (2991) wifi:enable tsf
W (2991) wifi:Haven't to connect to a suitable AP now!
I (3001) chip[DL]: Attempting to connect WiFi station interface
I (3011) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (3011) chip[DL]: I (3021) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (3021) wifi:state: init -> auth (b0)
Done driving station state, nothing else to do...
I (3551) chip[SVR]: Initializing subscription resumption storage...
I (3551) chip[SVR]: Server initializing...
I (3551) chip[TS]: Last Known Good Time: 2024-05-15T13:13:24
I (3571) chip[FP]: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x3FC5D006233120D9, FabricId 0x000000001A52AF64, NodeId 0x0000000033541060, VendorId 0x1349
I (4071) wifi:state: auth -> assoc (0)
I (4071) chip[FP]: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xB7711CDE10EFB877, FabricId 0x0000000000000001, NodeId 0x000000005A7F8756, VendorId 0x1384
I (4081) chip[DMG]: AccessControl: initializing
I (4091) chip[DMG]: Examples::AccessControlDelegate::Init
I (4091) chip[DMG]: AccessControl: setting
I (4101) chip[DMG]: DefaultAclStorage: initializing
I (4091) wifi:state: assoc -> run (10)
I (4121) chip[DMG]: DefaultAclStorage: 2 entries loaded
I (4131) wifi:connected with ORBI67I, aid = 1, channel 11, BW20, bssid = 42:98:b5:92:92:88
I (4131) wifi:security: WPA3-SAE, phy: bgn, rssi: -56
UpdateCommissionableInstanceName
random_instance_name: 1638062486092368845
I (4171) chip[ZCL]: Using ZAP configuration...
I (4171) esp_matter_cluster: Cluster plugin init common callback
I (4171) chip[DMG]: AccessControlCluster: initializing
I (4171) chip[ZCL]: 0x3f411814ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (4181) chip[ZCL]: Initiating Admin Commissioning cluster.
I (4191) chip[SVR]: Fabric already commissioned. Disabling BLE advertisement
I (4201) chip[IN]: CASE Server enabling CASE session setups
I (4201) chip[SVR]: Joining Multicast groups
I (4211) wifi:pm start, type: 1

I (4211) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (4221) wifi:dp: 4, bi: 102400, li: 4, scale listen interval from 307200 us to 409600 us
I (4231) wifi:AP's beacon interval = 102400 us, DTIM period = 4
I (4241) chip[SVR]: Server initialization complete
I (4241) chip[SVR]: Server Listening...
I (4241) esp_matter_core: Dynamic endpoint 0 added
I (4251) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (4261) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
I (4271) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (4281) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (4291) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00004003 is 0 **********
I (4311) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4321) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4331) chip[ZCL]: Endpoint 1 On/off already set to new value
I (4341) esp_matter_core: Dynamic endpoint 1 added
I (4341) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (4351) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
I (4371) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (4381) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (4391) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00004003 is 0 **********
I (4401) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4421) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4441) chip[ZCL]: I (4451) Endpoint 2 On/off already set to new value
I (4471) esp_matter_core: Dynamic endpoint 2 added
I (4471) RX_TASK: Read 18 bytes: ��K���$I@/�,<,\+
I (4441) wifi:<ba-add>idx:0 (ifx:0, 42:98:b5:92:92:88), tid:0, ssn:0, winSize:64
E (4531) chip[DL]: Long dispatch time: 985 ms, for event type 2
I (4571) chip[DL]: WIFI_EVENT_STA_START
I (4581) chip[DL]: Done driving station state, nothing else to do...
I (4581) SYSTEM: mDNS hostname set to: 4c7525f05d04.local
I (4631) app_main: fctry successfully read
I (4641) app_main: esp_secure_cert successfully read
I (4641) app_main: VID in DAC: 5226, PID in DAC: 32769
W (4651) SYSTEM: mDNS TXT record set
I (4651) chip[DL]: CHIPoBLE advertising stopped
I (4661) chip[IM]: Resuming 1 subscriptions in 0 seconds
I (4661) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (4671) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (4671) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (4681) chip[DL]: WiFi station interface connected
I (4691) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged
I (4701) chip[DL]: Done driving station state, nothing else to do...
I (4701) chip[DL]: Updating advertising data
E (9531) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (9531) task_wdt:  - IDLE0 (CPU 0)
E (9531) task_wdt: Tasks currently running:
E (9531) task_wdt: CPU 0: CHIP
E (9531) task_wdt: CPU 1: IDLE1
E (9531) task_wdt: Print CPU 0 (current core) backtrace

Backtrace: 0x401B7F97:0x3FFC00B0 0x4008F649:0x3FFC00E0 0x4000C050:0x3FFEED10 0x40008544:0x3FFEED20 0x4014F98A:0x3FFEED40 0x40156D0D:0x3FFEED60 0x401389B8:0x3FFEED80 0x401389C6:0x3FFEEDA0 0x40139114:0x3FFEEDC0 0x4013920E:0x3FFEEE20 0x40137F19:0x3FFEEE80 0x40137F61:0x3FFEEEA0 0x4013828E:0x3FFEEEC0 0x401382C1:0x3FFEEF30 0x40093CC2:0x3FFEEF50
0x401b7f97: task_wdt_timeout_handling at /Users/lawrenceko/esp/esp-idf/components/esp_system/task_wdt/task_wdt.c:441
 (inlined by) task_wdt_isr at /Users/lawrenceko/esp/esp-idf/components/esp_system/task_wdt/task_wdt.c:515
0x4008f649: _xt_lowint1 at /Users/lawrenceko/esp/esp-idf/components/xtensa/xtensa_vectors.S:1240
0x4000c050: xthal_get_ccount in ROM
0x40008544: ets_delay_us in ROM
0x4014f98a: esp_bt_controller_disable at /Users/lawrenceko/esp/esp-idf/components/bt/controller/esp32/bt.c:1717
0x40156d0d: nimble_port_deinit at /Users/lawrenceko/esp/esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:216
0x401389b8: chip::DeviceLayer::Internal::BLEManagerImpl::DeinitBLE() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:995
0x401389c6: chip::DeviceLayer::Internal::BLEManagerImpl::DeinitESPBleLayer() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:953
0x40139114: chip::DeviceLayer::Internal::BLEManagerImpl::DriveBLEState() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:824
0x4013920e: chip::DeviceLayer::Internal::BLEManagerImpl::_OnPlatformEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:391
0x40137f19: chip::DeviceLayer::Internal::BLEManager::OnPlatformEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/BLEManager.h:163
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::DispatchEventToDeviceLayer(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:321
0x40137f61: chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::_DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:295 (discriminator 1)
0x4013828e: chip::DeviceLayer::PlatformManager::DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:503
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:257
0x401382c1: chip::DeviceLayer::PlatformManager::RunEventLoop() at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:403
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::EventLoopTaskMain(void*) at /Users/lawrenceko/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:280
0x40093cc2: vPortTaskWrapper at /Users/lawrenceko/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134

SDKCONFIG: sdkconfig_matter.zip

law-ko commented 6 months ago

@shubhamdp Another crash log:

I've changed BLE to CPU1..

I (731) cpu_start: Multicore app
I (731) quad_psram: This chip is ESP32-PICO-V3-02
I (732) esp_psram: Found 2MB PSRAM device
I (734) esp_psram: Speed: 80MHz
I (738) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
I (987) esp_psram: SPI SRAM memory test OK
I (995) cpu_start: Pro cpu start user code
I (996) cpu_start: cpu freq: 160000000 Hz
I (996) cpu_start: Application information:
I (999) cpu_start: Project name:     outlet
I (1003) cpu_start: App version:      0.4.2
I (1008) cpu_start: Compile time:     May 16 2024 23:28:52
I (1014) cpu_start: ELF file SHA256:  117d2c619e12dc64...
I (1021) cpu_start: ESP-IDF:          v5.2.1
I (1025) cpu_start: Min chip rev:     v3.0
I (1030) cpu_start: Max chip rev:     v3.99 
I (1035) cpu_start: Chip rev:         v3.0
I (1040) heap_init: Initializing. RAM available for dynamic allocation:
I (1047) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1053) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1060) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1066) heap_init: At 3FFD8100 len 00007F00 (31 KiB): DRAM
I (1072) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1079) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1085) heap_init: At 4009E6C8 len 00001938 (6 KiB): IRAM
I (1092) esp_psram: Adding pool of 2048K of PSRAM memory to heap allocator
I (1100) spi_flash: detected chip: generic
I (1104) spi_flash: flash io: dio
W (1108) flash_encrypt: Flash encryption mode is DEVELOPMENT (not secure)
I (1117) nvs_sec_provider: NVS Encryption - Registering Flash encryption-based scheme...
I (1130) coexist: coex firmware version: 77cd7f8
I (1131) main_task: Started on CPU0
I (1141) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1141) main_task: Calling app_main()
I (1291) nvs: NVS partition "nvs" is encrypted.
W (1511) ledc: fade callback not in IRAM
I (1531) gpio: GPIO[25]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1561) gpio: GPIO[26]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1641) button: IoT Button Version: 3.1.3
I (1641) gpio: GPIO[13]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1671) app_matter: Outlet one created with endpoint_id 1
I (1671) app_matter: Outlet two created with endpoint_id 2
hostname endpoint id: 0
I (1751) wifi:wifi driver task: 3ffdd660, prio:23, stack:6656, core=0
I (1801) wifi:wifi firmware version: a9f5b59
I (1801) wifi:wifi certification version: v7.0
I (1801) wifi:config NVS flash: enabled
I (1801) wifi:config nano formating: disabled
I (1811) wifi:Init data frame dynamic rx buffer num: 32
I (1811) wifi:Init static rx mgmt buffer num: 5
I (1821) wifi:Init management short buffer num: 32
I (1821) wifi:Init static tx buffer num: 16
I (1831) wifi:Init tx cache buffer num: 32
I (1831) wifi:Init static rx buffer size: 1600
I (1831) wifi:Init static rx buffer num: 10
I (1841) wifi:Init dynamic rx buffer num: 32
I (1841) wifi_init: rx ba win: 6
I (1851) wifi_init: tcpip mbox: 32
I (1851) wifi_init: udp mbox: 6
I (1851) wifi_init: tcp mbox: 6
I (1861) wifi_init: tcp tx win: 5744
I (1861) wifi_init: tcp rx win: 5744
I (1871) wifi_init: tcp mss: 1440
I (1871) wifi_init: WiFi/LWIP prefer SPIRAM
I (1871) wifi_init: WiFi IRAM OP enabled
I (1881) wifi_init: WiFi RX IRAM OP enabled
I (1971) chip[DL]: NVS set: chip-counters/reboot-count = 3 (0x3)
I (1981) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (1981) BTDM_INIT: BT controller compile version [0f0c5a2]
I (1981) BTDM_INIT: Bluetooth MAC: 4c:75:25:f0:5d:06
I (1991) phy_init: phy_version 4791,2c4672b,Dec 20 2023,16:06:06
I (2331) CHIP[DL]: BLE host-controller synced
I (2841) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (2851) chip[DL]: CHIPoBLE advertising started
E (2851) chip[DL]: Long dispatch time: 866 ms, for event type 2
I (2851) chip[DL]: Starting ESP WiFi layer
I (2861) wifi:mode : sta (4c:75:25:f0:5d:04)
I (2861) wifi:enable tsf
W (2861) wifi:Haven't to connect to a suitable AP now!
I (2871) chip[DL]: Attempting to connect WiFi station interface
I (2881) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (2881) chip[DL]: Done driving station state, nothing else to do...
I (2891) chip[SVR]: Initializing subscription resumption storage...
I (2881) wifi:new:<6,1>, old:<1,0>, ap:<255,255>, sta:<6,1>, prof:1
I (2901) wifi:state: init -> auth (b0)
I (2991) chip[SVR]: Server initializing...
I (3021) chip[TS]: Last Known Good Time: 2024-05-16T17:03:17
I (3321) chip[FP]: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x3FC5D006233120D9, FabricId 0x000000001A52AF64, NodeId 0x00000000450B6E09, VendorId 0x1349
I (3471) chip[FP]: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xB7711CDE10EFB877, FabricId 0x0000000000000001, NodeId 0x0000000077DE46F4, VendorId 0x1384
I (3471) chip[DMG]: AccessControl: initializing
I (3481) chip[DMG]: Examples::AccessControlDelegate::Init
I (3481) chip[DMG]: AccessControl: setting
I (3491) chip[DMG]: DefaultAclStorage: initializing
I (3571) chip[DMG]: DefaultAclStorage: 2 entries loaded
I (3991) wifi:state: auth -> assoc (0)
I (4001) wifi:state: assoc -> run (10)
I (4011) chip[ZCL]: Using ZAP configuration...
I (4011) esp_matter_cluster: Cluster plugin init common callback
I (4011) chip[DMG]: AccessControlCluster: initializing
I (4011) chip[ZCL]: 0x3f411675ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (4021) chip[ZCL]: Initiating Admin Commissioning cluster.
I (4031) chip[SVR]: Fabric already commissioned. Disabling BLE advertisement
I (4041) chip[IN]: CASE Server enabling CASE session setups
I (4041) chip[SVR]: Joining Multicast groups
I (4061) wifi:connected with ORBI67I, aid = 3, channel 6, 40U, bssid = 42:98:b5:96:60:22
I (4061) wifi:security: WPA3-SAE, phy: bgn, rssi: -22
I (4061) chip[SVR]: Server initialization complete
I (4071) chip[SVR]: Server Listening...
I (4071) esp_matter_core: Dynamic endpoint 0 added
I (4081) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (4091) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
I (4101) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (4111) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (4121) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00004003 is 0 **********
I (4141) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4151) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4161) chip[ZCL]: Endpoint 1 On/off already set to new value
I (4171) esp_matter_core: Dynamic endpoint 1 added
I (4171) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (4181) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
I (4191) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (4211) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (4221) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00004003 is 0 **********
I (4231) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4241) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4251) chip[ZCL]: Endpoint 2 On/off already set to new value
I (4261) esp_matter_core: Dynamic endpoint 2 added
I (4271) wifi:pm start, type: 1

I (4271) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (4281) wifi:dp: 4, bi: 102400, li: 4, scale listen interval from 307200 us to 409600 us
I (4281) wifi:AP's beacon interval = 102400 us, DTIM period = 4
E (4301) chip[DL]: Long dispatch time: 1407 ms, for event type 2
I (4301) chip[DL]: WIFI_EVENT_STA_START
I (4301) chip[DL]: Done driving station state, nothing else to do...
I (4311) SYSTEM: mDNS hostname set to: 4c7525f05d04.local
I (4331) app_main: fctry successfully read
I (4331) wifi:<ba-add>idx:0 (ifx:0, 42:98:b5:96:60:22), tid:0, ssn:0, winSize:64
W (4341) SYSTEM: mDNS TXT record set
I (4341) chip[DL]: CHIPoBLE advertising stopped
I (4351) chip[IM]: Resuming 1 subscriptions in 0 seconds
I (4351) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (4351) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (4361) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (4371) chip[DL]: WiFi station interface connected
I (4371) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged
I (4381) chip[DL]: Done driving station state, nothing else to do...
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4015879d  PS      : 0x00060030  A0      : 0x80158eec  A1      : 0x3ffbabf0  
0x4015879d: npl_freertos_eventq_put at /Volumes/BX100SSD/Development/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/npl_os_freertos.c:304

A2      : 0x3ffd66cc  A3      : 0x3ffd67e8  A4      : 0x80093ed4  A5      : 0x3ffee8a0  
A6      : 0x00000003  A7      : 0x3ffd69c4  A8      : 0x00000000  A9      : 0x007bee60  
A10     : 0x003fffff  A11     : 0x00000005  A12     : 0x00000000  A13     : 0x007bdc20  
A14     : 0x003fffff  A15     : 0x00000000  SAR     : 0x00000001  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000000  LBEG    : 0x400832e5  LEND    : 0x400832ed  LCOUNT  : 0x00000027  
0x400832e5: esp_timer_impl_get_counter_reg at /Volumes/BX100SSD/Development/esp/esp-idf/components/esp_timer/src/esp_timer_impl_lac.c:118
0x400832ed: esp_timer_impl_get_counter_reg at /Volumes/BX100SSD/Development/esp/esp-idf/components/esp_timer/src/esp_timer_impl_lac.c:128

Backtrace: 0x4015879a:0x3ffbabf0 0x40158ee9:0x3ffbac30 0x400d63cd:0x3ffbac50 0x40093cc2:0x3ffbac80
0x4015879a: npl_freertos_eventq_put at /Volumes/BX100SSD/Development/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/npl_os_freertos.c:302
0x40158ee9: ble_npl_eventq_put at /Volumes/BX100SSD/Development/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:173
 (inlined by) ble_npl_event_fn_wrapper at /Volumes/BX100SSD/Development/esp/esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/src/npl_os_freertos.c:653
0x400d63cd: timer_process_alarm at /Volumes/BX100SSD/Development/esp/esp-idf/components/esp_timer/src/esp_timer.c:453
 (inlined by) timer_task at /Volumes/BX100SSD/Development/esp/esp-idf/components/esp_timer/src/esp_timer.c:479
0x40093cc2: vPortTaskWrapper at /Volumes/BX100SSD/Development/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134

law-ko commented 6 months ago

@shubhamdp Another crash..

I (672) cpu_start: Multicore app
I (672) quad_psram: This chip is ESP32-PICO-V3-02
I (672) esp_psram: Found 2MB PSRAM device
I (674) esp_psram: Speed: 80MHz
I (678) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
I (928) esp_psram: SPI SRAM memory test OK
I (936) cpu_start: Pro cpu start user code
I (936) cpu_start: cpu freq: 160000000 Hz
I (936) cpu_start: Application information:
I (939) cpu_start: Project name:     outlet
I (944) cpu_start: App version:      0.4.2
I (949) cpu_start: Compile time:     May 16 2024 23:28:52
I (955) cpu_start: ELF file SHA256:  117d2c619e12dc64...
I (961) cpu_start: ESP-IDF:          v5.2.1
I (966) cpu_start: Min chip rev:     v3.0
I (970) cpu_start: Max chip rev:     v3.99 
I (975) cpu_start: Chip rev:         v3.0
I (980) heap_init: Initializing. RAM available for dynamic allocation:
I (987) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (993) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (999) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1005) heap_init: At 3FFD8100 len 00007F00 (31 KiB): DRAM
I (1012) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1018) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1024) heap_init: At 4009E6C8 len 00001938 (6 KiB): IRAM
I (1031) esp_psram: Adding pool of 2048K of PSRAM memory to heap allocator
I (1039) spi_flash: detected chip: generic
I (1043) spi_flash: flash io: dio
W (1047) flash_encrypt: Flash encryption mode is DEVELOPMENT (not secure)
I (1056) nvs_sec_provider: NVS Encryption - Registering Flash encryption-based scheme...
I (1070) coexist: coex firmware version: 77cd7f8
I (1071) main_task: Started on CPU0
I (1081) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1081) main_task: Calling app_main()
I (1241) nvs: NVS partition "nvs" is encrypted.
I (1481) gpio: GPIO[25]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1501) gpio: GPIO[26]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1511) OUTLET: Outlet 1 & 2: OFF
I (1571) button: IoT Button Version: 3.1.3
I (1571) gpio: GPIO[13]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1581) TX_TASK: Wrote 11 bytes
I (1591) TX_TASK: 0x3ffdb280   a6 fe c1 f8 2b 07 51 00  0c 10 12                 |....+.Q....|
I (1611) app_matter: Outlet one created with endpoint_id 1
I (1611) app_matter: Outlet two created with endpoint_id 2
I (1701) wifi:wifi driver task: 3ffdd660, prio:23, stack:6656, core=0
I (1751) wifi:wifi firmware version: a9f5b59
I (1751) wifi:wifi certification version: v7.0
I (1751) wifi:config NVS flash: enabled
I (1751) wifi:config nano formating: disabled
I (1751) wifi:Init data frame dynamic rx buffer num: 32
I (1761) wifi:Init static rx mgmt buffer num: 5
I (1761) wifi:Init management short buffer num: 32
I (1771) wifi:Init static tx buffer num: 16
I (1771) wifi:Init tx cache buffer num: 32
I (1771) wifi:Init static rx buffer size: 1600
I (1781) wifi:Init static rx buffer num: 10
I (1781) wifi:Init dynamic rx buffer num: 32
I (1791) wifi_init: rx ba win: 6
I (1791) wifi_init: tcpip mbox: 32
I (1791) wifi_init: udp mbox: 6
I (1801) wifi_init: tcp mbox: 6
I (1801) wifi_init: tcp tx win: 5744
I (1801) wifi_init: tcp rx win: 5744
I (1811) wifi_init: tcp mss: 1440
I (1811) wifi_init: WiFi/LWIP prefer SPIRAM
I (1821) wifi_init: WiFi IRAM OP enabled
I (1821) wifi_init: WiFi RX IRAM OP enabled
I (1911) chip[DL]: NVS set: chip-counters/reboot-count = 3 (0x3)
I (1921) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (1921) BTDM_INIT: BT controller compile version [0f0c5a2]
I (1931) BTDM_INIT: Bluetooth MAC: 4c:75:25:f0:5d:06
I (1931) phy_init: phy_version 4791,2c4672b,Dec 20 2023,16:06:06
I (2271) CHIP[DL]: BLE host-controller synced
I (2771) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (2781) chip[DL]: CHIPoBLE advertising started
E (2781) chip[DL]: Long dispatch time: 855 ms, for event type 2
I (2781) chip[DL]: Starting ESP WiFi layer
I (2791) wifi:mode : sta (4c:75:25:f0:5d:04)
I (2791) wifi:enable tsf
W (2791) wifi:Haven't to connect to a suitable AP now!
I (2801) chip[DL]: Attempting to connect WiFi station interface
I (2811) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (2811) chip[DL]: Done driving station state, nothing else to do...
I (2821) chip[SVR]: Initializing subscription resumption storage...
I (2811) wifi:new:<6,1>, old:<1,0>, ap:<255,255>, sta:<6,1>, prof:1
I (2831) wifi:state: init -> auth (b0)
I (2901) chip[SVR]: Server initializing...
I (2941) chip[TS]: Last Known Good Time: 2024-05-16T17:20:57
I (3291) chip[FP]: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x3FC5D006233120D9, FabricId 0x000000001A52AF64, NodeId 0x000000009CD0BD42, VendorId 0x1349
I (3391) chip[FP]: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xB7711CDE10EFB877, FabricId 0x0000000000000001, NodeId 0x00000000A24A37AE, VendorId 0x1384
I (3401) chip[DMG]: AccessControl: initializing
I (3411) chip[DMG]: Examples::AccessControlDelegate::Init
I (3411) chip[DMG]: AccessControl: setting
I (3421) chip[DMG]: DefaultAclStorage: initializing
I (3431) chip[DMG]: DefaultAclStorage: 2 entries loaded
I (3531) chip[ZCL]: Using ZAP configuration...
I (3531) esp_matter_cluster: Cluster plugin init common callback
I (3531) chip[DMG]: AccessControlCluster: initializing
I (3531) chip[ZCL]: 0x3f411675ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (3551) chip[ZCL]: Initiating Admin Commissioning cluster.
I (3551) chip[SVR]: Fabric already commissioned. Disabling BLE advertisement
I (3571) chip[IN]: CASE Server enabling CASE session setups
I (3571) chip[SVR]: Joining Multicast groups
I (3651) chip[SVR]: Server initialization complete
I (3651) chip[SVR]: Server Listening...
I (3651) esp_matter_core: Dynamic endpoint 0 added
I (3651) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (3671) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
I (3691) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (3691) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (3711) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00004003 is 0 **********
I (3711) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 1 **********
I (3731) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 1 **********
I (3731) chip[ZCL]: Toggle ep1 on/off from state 1 to 0
I (3751) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (3891) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (3891) chip[ZCL]: Off completed. reset OnTime to  0
I (3891) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00004001 is 0 **********
I (3911) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000005's Attribute 0x00000003 is 0 **********
I (3931) esp_matter_core: Dynamic endpoint 1 added
I (3931) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (3931) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
I (3951) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (3971) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (3971) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00004003 is 0 **********
I (3991) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00000000 is 1 **********
I (3991) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00000000 is 1 **********
I (4011) chip[ZCL]: Toggle ep2 on/off from state 1 to 0
I (4011) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (4111) esp_matter_attribute: ********** R : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (4111) chip[ZCL]: Off completed. reset OnTime to  0
I (4111) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000006's Attribute 0x00004001 is 0 **********
I (4121) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000005's Attribute 0x00000003 is 0 **********
I (4141) esp_matter_core: Dynamic endpoint 2 added
I (4121) wifi:state: auth -> assoc (0)
E (4151) chip[DL]: Long dispatch time: 1333 ms, for event type 2
I (4151) chip[DL]: WIFI_EVENT_STA_START
I (4161) wifi:state: assoc -> run (10)
I (4161) chip[DL]: Attempting to connect WiFi station interface
E (4171) wifi:sta is connecting, return error
E (4171) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (4181) SYSTEM: mDNS hostname set to: 4c7525f05d04.local
I (4191) wifi:connected with ORBI67I, aid = 3, channel 6, 40U, bssid = 42:98:b5:96:60:22
I (4191) wifi:security: WPA3-SAE, phy: bgn, rssi: -24
I (4201) wifi:pm start, type: 1

I (4201) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (4211) wifi:dp: 4, bi: 102400, li: 4, scale listen interval from 307200 us to 409600 us
I (4211) wifi:AP's beacon interval = 102400 us, DTIM period = 4
I (4231) app_main: fctry successfully read
I (4231) app_main: esp_secure_cert successfully read
I (4241) app_main: VID in DAC: 5226, PID in DAC: 32769
W (4251) SYSTEM: mDNS TXT record set
I (4251) chip[DL]: CHIPoBLE advertising stopped
I (4261) chip[IM]: Resuming 1 subscriptions in 0 seconds
I (4271) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (4271) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (4281) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (4281) chip[DL]: WiFi station interface connected
I (4291) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged
I (4301) chip[DL]: Done driving station state, nothing else to do...
I (4331) chip[DL]: BLE deinit successful and memory reclaimed
I (4331) chip[DL]: Updating advertising data
I (4331) app_main: BLE is deinitialized
I (4351) chip[DIS]: Resolving 3FC5D006233120D9:0000000027DB8A03 ...
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x4014fcf7  PS      : 0x00060430  A0      : 0x80172c2c  A1      : 0x3ffbaba0  
0x4014fcf7: queue_send_hlevel_wrapper at /Volumes/BX100SSD/Development/esp/esp-idf/components/bt/controller/esp32/bt.c:744

A2      : 0x00000000  A3      : 0x3ffbabc0  A4      : 0x00000000  A5      : 0x3ffee5d0  
A6      : 0x00000003  A7      : 0x00060023  A8      : 0x00000001  A9      : 0x3ffc3b58  
A10     : 0x00000000  A11     : 0x3ffb7954  A12     : 0x80093ed4  A13     : 0x3ffd9d20  
A14     : 0x00000003  A15     : 0x00060023  SAR     : 0x00000019  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
0x4000c2e0: memcpy in ROM
0x4000c2f6: memcpy in ROM

Backtrace: 0x4014fcf4:0x3ffbaba0 0x40172c29:0x3ffbabc0 0x4015f8d6:0x3ffbabf0 0x401ec81d:0x3ffbac10 0x401ec829:0x3ffbac30 0x400d63cd:0x3ffbac50 0x40093cc2:0x3ffbac80
0x4014fcf4: queue_send_hlevel_wrapper at /Volumes/BX100SSD/Development/esp/esp-idf/components/bt/controller/esp32/bt.c:741
0x40172c29: btdm_task_post at ??:?
0x4015f8d6: coex_schm_btdm_callback_v2 at ??:?
0x401ec81d: coex_core_register_start_cb at ??:?
0x401ec829: coex_core_register_start_cb at ??:?
0x400d63cd: timer_process_alarm at /Volumes/BX100SSD/Development/esp/esp-idf/components/esp_timer/src/esp_timer.c:453
 (inlined by) timer_task at /Volumes/BX100SSD/Development/esp/esp-idf/components/esp_timer/src/esp_timer.c:479
0x40093cc2: vPortTaskWrapper at /Volumes/BX100SSD/Development/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134

law-ko commented 2 months ago

@shubhamdp Please see this issue for related-crash: https://github.com/espressif/esp-matter/issues/1079

espressif / esp-matter

Sproadic LoadProhibited (CON-907) #748