espressif
E (39013585) chip[CSL]: PacketBuffer: pool EMPTY. B (CON-792)
I left the off-the-shelf esp-matter light demo running over night on ESP32 with 4MB of PSRAM. And it ran out of packet buffers. This is unchanged light demo code with nothing but a wildcard subscription monitoring it for 12 hours and it failed.
Why aren't the packet buffers being allocated out of PSRAM? I have 3.9MB of free PSRAM. The IRAM is getting fragmented to the point that the packet buffers can't be allocated.
I had four identical devices running, all four failed.
I (39010845) chip[IN]: (S) Sending msg 266512572 on secure session with LSID: 11432
E (39013585) chip[CSL]: PacketBuffer: pool EMPTY. B
Heap summary for capabilities 0x00000800:
At 0x3ffb2730 len 15448 free 4 allocated 14860 min_free 4
largest_free_block 0 alloc_blocks 42 free_blocks 0 total_blocks 42
E (39013595) chip[DL]: At 0x3ffaff10 len 240 free 4 allocated 28 min_free 4
largest_free_block 0 alloc_blocks 2 free_blocks 0 total_blocks 2
Failed to post event to CHIP Platform event queue At 0x3ffb6388 len 7288 free 4 allocated 6668 min_free 4
largest_free_block 0 alloc_blocks 59 free_blocks 0 total_blocks 59
At 0x3ffb9a20 len 16648 free 64 allocated 15312 min_free 4
largest_free_block 20 alloc_blocks 134 free_blocks 3 total_blocks 137
E (39013635) chip[CSL]: Failed to queue CHIP System Layer lambda event: 1000000
At 0x3ffd5710 len 43248 free 72 allocated 40924 min_free 4
largest_free_block 24 alloc_blocks 362 free_blocks 3 total_blocks 365
At 0x3ffe0440 len 15072 free 4 allocated 14552 min_free 4
largest_free_block 0 alloc_blocks 25 free_blocks 0 total_blocks 25
At 0x3ffe4350 len 113840 free 13412 allocated 98880 min_free 1524
largest_free_block 7936 alloc_blocks 169 free_blocks 10 total_blocks 179
At 0x4009ee84 len 4476 free 4072 allocated 20 min_free 4040
largest_free_block 3840 alloc_blocks 1 free_blocks 1 total_blocks 2
Totals:
free 17636 allocated 191244 min_free 5588 largest_free_block 7936
another example
I (29575155) chip[IN]: (S) Sending msg 155730458 on secure session with LSID: 33234
I (29575265) chip[EM]: >>> [E:1933i S:33234 M:177711665 (Ack:155730458)] (S) Msg RX from 2:AB0DE00000000000 [1443] --- Type 0001:01 (IM:StatusResponse)
I (29575275) chip[IM]: Received status response, status is 0x00
I (29575285) chip[EM]: <<< [E:1933i S:33234 M:155730459 (Ack:177711665)] (S) Msg TX to 2:AB0DE00000000000 [1443] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (29575295) chip[IN]: (S) Sending msg 155730459 on secure session with LSID: 33234
I (29577605) ROUTE_HOOK: Received RIO
I (29577605) ROUTE_HOOK: prefix FD89:EBF4:10D6:: lifetime 1800
I (29585175) chip[EM]: <<< [E:1934i S:33234 M:155730460] (S) Msg TX to 2:AB0DE00000000000 [1443] --- Type 0001:05 (IM:ReportData)
I (29585175) chip[IN]: (S) Sending msg 155730460 on secure session with LSID: 33234
I (29585245) chip[EM]: >>> [E:1934i S:33234 M:177711666 (Ack:155730460)] (S) Msg RX from 2:AB0DE00000000000 [1443] --- Type 0001:01 (IM:StatusResponse)
I (29585255) chip[IM]: Received status response, status is 0x00
I (29585275) chip[EM]: <<< [E:1934i S:33234 M:155730461 (Ack:177711666)] (S) Msg TX to 2:AB0DE00000000000 [1443] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (29585275) chip[IN]: (S) Sending msg 155730461 on secure session with LSID: 33234
E (29591755) chip[CSL]: PacketBuffer: pool EMPTY. B
Heap summary for capabilities 0x00000800:
At 0x3ffb2730 len 15448 free 4 allocated 14860 min_free 4
largest_free_block 0 alloc_blocks 42 free_blocks 0 total_blocks 42
E (29591765) chip[DL]: At 0x3ffaff10 len 240 free 4 allocated 28 min_free 4
largest_free_block 0 alloc_blocks 2 free_blocks 0 total_blocks 2
Failed to post event to CHIP Platform event queue At 0x3ffb6388 len 7288 free 4 allocated 6676 min_free 4
largest_free_block 0 alloc_blocks 57 free_blocks 0 total_blocks 57
At 0x3ffb9a20 len 16648 free 24 allocated 15400 min_free 4
largest_free_block 16 alloc_blocks 122 free_blocks 1 total_blocks 123
E (29591805) chip[CSL]: At 0x3ffd5710 len 43248 free 4 allocated 40980 min_free 4
largest_free_block 0 alloc_blocks 365 free_blocks 0 total_blocks 365
Failed to queue CHIP System Layer lambda event: 1000000
At 0x3ffe0440 len 15072 free 4 allocated 14552 min_free 4
largest_free_block 0 alloc_blocks 25 free_blocks 0 total_blocks 25
At 0x3ffe4350 len 113840 free 7468 allocated 104732 min_free 2460
largest_free_block 3200 alloc_blocks 192 free_blocks 7 total_blocks 199
E (29591845) chip[DL]: At 0x4009ee84 len 4476 free 4072 allocated 20 min_free 4040
largest_free_block 3840 alloc_blocks 1 free_blocks 1 total_blocks 2
Totals:
Failed to post event to CHIP Platform event queue
free 11604 allocated 197232 min_free 6524 largest_free_block 3840
E (29591865) chip[CSL]: Failed to queue CHIP System Layer lambda event: 1000000
E (29591885) chip[DIS]: Failed to reply to query: b
E (29591895) chip[DL]: Failed to post event to CHIP Platform event queue
E (29591895) chip[CSL]: Failed to queue CHIP System Layer lambda event: 1000000
E (29591925) chip[DL]: Failed to post event to CHIP Platform event queue
E (29591925) chip[CSL]: Failed to queue CHIP System Layer lambda event: 1000000
E (29591935) chip[DL]: Failed to post event to CHIP Platform event queue
E (29591935) chip[CSL]: Failed to queue CHIP System Layer lambda event: 1000000
E (29591955) chip[DL]: Failed to post event to CHIP Platform event queue
E (29591955) chip[CSL]: Failed to queue CHIP System Layer lambda event: 1000000
I (31) boot: ESP-IDF v5.1.1 2nd stage bootloader
I (31) boot: compile time Sep 23 2023 21:49:07
I (31) boot: Multicore bootloader
I (35) boot: chip revision: v1.0
I (39) boot.esp32: SPI Speed : 40MHz
I (43) boot.esp32: SPI Mode : DIO
I (48) boot.esp32: SPI Flash Size : 4MB
I (52) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (61) boot: ## Label Usage Type ST Offset Length
I (69) boot: 0 esp_secure_cert unknown 3f 06 0000d000 00002000
I (76) boot: 1 nvs WiFi data 01 02 00010000 0000b000
I (84) boot: 2 nvs_keys NVS keys 01 04 0001b000 00001000
I (91) boot: 3 otadata OTA data 01 00 0001c000 00002000
I (99) boot: 4 phy_init RF data 01 01 0001e000 00001000
I (106) boot: 5 ota_0 OTA app 00 10 00020000 001e0000
I (114) boot: 6 ota_1 OTA app 00 11 00200000 001e0000
I (121) boot: 7 fctry WiFi data 01 02 003e0000 00006000
I (129) boot: End of partition table
I (133) boot: No factory image, trying OTA 0
I (138) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=4ba68h (309864) map
I (258) esp_image: segment 1: paddr=0006ba90 vaddr=3ff80000 size=00004h ( 4) load
I (259) esp_image: segment 2: paddr=0006ba9c vaddr=3ffbdb60 size=0457ch ( 17788) load
I (271) esp_image: segment 3: paddr=00070020 vaddr=400d0020 size=13e3f8h (1303544) map
I (743) esp_image: segment 4: paddr=001ae420 vaddr=3ffc20dc size=017ech ( 6124) load
I (746) esp_image: segment 5: paddr=001afc14 vaddr=40080000 size=1da1ch (121372) load
I (815) boot: Loaded app from partition at offset 0x20000
I (853) boot: Set actual ota_seq=1 in otadata[0]
I (853) boot: Disabling RNG early entropy source...
I (864) cpu_start: Multicore app
I (865) quad_psram: This chip is ESP32-D0WD
I (865) esp_psram: Found 8MB PSRAM device
I (868) esp_psram: Speed: 40MHz
I (872) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (880) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (889) cpu_start: Pro cpu up.
I (893) cpu_start: Starting app cpu, entry point is 0x40081740
0x40081740: call_start_cpu1 at /home/jonsmirl/esp/esp-idf/components/esp_system/port/cpu_start.c:154
I (0) cpu_start: App cpu up.
I (1763) esp_psram: SPI SRAM memory test OK
I (1771) cpu_start: Pro cpu start user code
I (1771) cpu_start: cpu freq: 160000000 Hz
I (1771) cpu_start: Application information:
I (1775) cpu_start: Project name: lowpan
I (1780) cpu_start: App version: v1.0
I (1784) cpu_start: Compile time: Sep 23 2023 22:00:30
I (1791) cpu_start: ELF file SHA256: e624bed2ead73d31...
I (1797) cpu_start: ESP-IDF: v5.1.1
I (1802) cpu_start: Min chip rev: v0.0
I (1806) cpu_start: Max chip rev: v3.99
I (1811) cpu_start: Chip rev: v1.0
I (1816) heap_init: Initializing. RAM available for dynamic allocation:
I (1824) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1830) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1836) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1842) heap_init: At 3FFD7830 len 000087D0 (33 KiB): DRAM
I (1848) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1855) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1861) heap_init: At 4009DA1C len 000025E4 (9 KiB): IRAM
I (1868) esp_psram: Adding pool of 4096K of PSRAM memory to heap allocator
I (1876) spi_flash: detected chip: generic
I (1880) spi_flash: flash io: dio
@jonsmirl Which branch of esp-matter does this use? main or release/v1.1. We have had long duration runs with release/v1.1 devices (light example) commissioned into 2 ecosystems (with their subscriptions) running fine for more than 3 weeks.
I was using the main branch at commit cd325c6fa4203c45707ecb8b5351b7303347acb7
This is not a problem with leaving the device booted for three weeks. It is specifically a problem with leaving a wildcard subscription monitoring the device. The wildcard subscription makes the memory allocations constantly churn. After about 12 hours I can't allocate packet buffers anymore due to fragmentation.
For me, a solution would be a malloc which forces everything into PSRAM unless it is marked as having to go into IRAM. I have megabytes of unused PSRAM just sitting there. I have ALL of the alloc strategies already set to PSRAM.
For a more general solution -- I think you need to work on memory management until a long running subscription does not cause any allocs. For example if I leave a subscription running for a week there should be zero allocations done once the subscription is established.
Hi @jonsmirl Can you try with below patch, it uses the ESP32's heap area for allocating the system buffer pool.
curl https://github.com/shubhamdp/connectedhomeip/commit/8bd558c85bebb56ecb9d80c1d5993dab3bc25c20.patch | git am
You need quotes around the menu string. bool "Use heap memory for system buffer pool"
[0/1] cd /home/jonsmirl/lowpan/build && /home/jonsmirl/.espressif/...-env IDF_ENV_FPGA= --output config /home/jonsmirl/lowpan/sdkconfig
/home/jonsmirl/aosp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/components/chip/Kconfig:138: warning: style: quotes recommended around 'Use' in 'bool Use heap memory for system buffer pool'
Traceback (most recent call last):
I have this installed on my test nodes now. It is harder to test since we are looking for a negative result. I will run it for several days and see if we hit the old problems.
Moving those packet buffers to PSRAM has huge impact on free IRAM. I went from 15KB free and fragmented. To 78K free now.
Too many buffers are getting allocated? When I first turn on a wildcard report there is a flurry of packet activity. Maybe that is getting too many outstanding unacknowledged messages? Also, if an allocation occurs while those unacknowledged messages are active, it will get allocated after the packet buffer in memory. This could be the mechanism which is fragmenting the memory.
I would have expected to see a hard cap on number of packet buffers in the system. Then if more are needed, you block until previous ones free up. So you would statically allocate 3-4 packet buffers at boot and then never again.
Heap summary for capabilities 0x00000800:
At 0x3fcb3134 len 32767 free 31943 allocated 84 min_free 31915
largest_free_block 31744 alloc_blocks 1 free_blocks 1 total_blocks 2
At 0x3fcae548 len 242120 free 144 allocated 239216 min_free 4
largest_free_block 72 alloc_blocks 455 free_blocks 3 total_blocks 458
At 0x3fce9710 len 22308 free 6332 allocated 14768 min_free 1036
largest_free_block 4352 alloc_blocks 118 free_blocks 7 total_blocks 125
At 0x3fcf0000 len 32768 free 32032 allocated 0 min_free 11584
largest_free_block 31744 alloc_blocks 0 free_blocks 1 total_blocks 1
At 0x600fe014 len 8148 free 7768 allocated 0 min_free 7768
largest_free_block 7680 alloc_blocks 0 free_blocks 1 total_blocks 1
Totals:
free 78219 allocated 254068 min_free 52307 largest_free_block 31744
Do note that moving these buffers to PSRAM only helps people using PSRAM and does not fix this problem on the C3.
I have added the C3 on the long duration test, will check how it behaves.
I would hit this within two days on C3 using light demo and a wildcard subscription monitoring it. The key here is 'wildcard subscription' monitoring it. All of the controllers use those to watch the state on the devices.
I'm at two days now with this turned on for PSRAM and I haven't had a Packet Buffer alloc failure. I am going to stop the test and change the code to periodically dump out PSRAM alloc statistics to ensure it is not leaking PSRAM. Since i have megabytes of free PSRAM it could be months before I run out due to a leak.
However, I still hit this one all of the time: https://github.com/espressif/esp-matter/issues/656 You need to make that queue longer and update the example sdkconfig.
Also, if you bump the CHIP version up, there is a fix for this one:
E (84098219) chip[EM]: OnMessageReceived failed, err = 70
As for the C3 --- The code should block and wait for a buffer to free instead of failing when there is insufficient RAM. Failing just cascades the problem by triggering even more packets due to retries. Blocking will throttle packet generation.
@jonsmirl Thanks for the help in testing it. I have been running this patch on C3 with one wildcard subscription and did not see this problem.
Thanks for the heads up will bump the CHIP version.
These are my old bugs for same problem. those were on C3. Currently my test lights are ESP32. https://github.com/espressif/esp-matter/issues/434 https://github.com/espressif/esp-matter/issues/555
This is a memory dump which was inserted into CHIP code right after the error message printed. https://github.com/espressif/esp-matter/issues/555#issuecomment-1704435684
diff --git a/src/system/SystemPacketBuffer.cpp b/src/system/SystemPacketBuffer.cpp
index 209a80b821..589bcc0924 100644
--- a/src/system/SystemPacketBuffer.cpp
+++ b/src/system/SystemPacketBuffer.cpp
@@ -150,7 +150,10 @@ void PacketBufferHandle::InternalRightSize()
PacketBuffer * newBuffer = reinterpret_cast<PacketBuffer *>(chip::Platform::MemoryAlloc(blockSize));
if (newBuffer == nullptr)
{
- ChipLogError(chipSystemLayer, "PacketBuffer: pool EMPTY.");
+ ChipLogError(chipSystemLayer, "PacketBuffer: pool EMPTY. A");
+#ifdef ESP_PLATFORM
+ heap_caps_print_heap_info(MALLOC_CAP_INTERNAL);
+#endif
return;
}
@@ -536,7 +539,10 @@ PacketBufferHandle PacketBufferHandle::New(size_t aAvailableSize, uint16_t aRese
if (lPacket == nullptr)
{
- ChipLogError(chipSystemLayer, "PacketBuffer: pool EMPTY.");
+ ChipLogError(chipSystemLayer, "PacketBuffer: pool EMPTY. B");
+#ifdef ESP_PLATFORM
+ heap_caps_print_heap_info(MALLOC_CAP_INTERNAL);
+#endif
return PacketBufferHandle();
}
Something is definitely broken. Look at this trace from the light demo, the unit is just sitting idle. Some transient thing is eating up huge amounts of memory. You can see from trace that there is no Matter traffic.
At 9585776 -- 61,196 bytes free At 9605776 -- 47,180 bytes free then it comes back to 61,196 free
Then it hits PacketBuffer: pool EMPTY! only 11,108 free and there is not a large enough block to make a packet buffer. and that chains into a MDNS failure.
Then at 9705956 -- back to 61,196 bytes free.
We are lucky in this trace that there were two heap dump quite close to each other. At 0x3ffb9a20 len 16648 free 700 allocated 14740 min_free 4 largest_free_block 672 alloc_blocks 118 free_blocks 2 total_blocks 120 At 0x3ffe4350 len 113840 free 56316 allocated 56156 min_free 216 largest_free_block 53248 alloc_blocks 124 free_blocks 6 total_blocks 130 changed to: At 0x3ffb9a20 len 16648 free 68 allocated 15304 min_free 4 largest_free_block 24 alloc_blocks 135 free_blocks 3 total_blocks 138 At 0x3ffe4350 len 113840 free 7504 allocated 104712 min_free 216 largest_free_block 1472 alloc_blocks 188 free_blocks 16 total_blocks 204
So what suddenly ate 49,160 bytes of memory? It has to be something to do with network buffers. This node didn't have PSRAM enabled, but it did have WIFI_DYNAMIC buffers turned on with a count of 32. It is using the CHIP MDNS code. sdkconfig.txt
My guess? Something to do with MDNS. My home network has about 100 devices on it and dozens of them are using MDNS. Maybe one of them is doing something to trigger a bad response out of the chip MDNS implementation. trace.txt
I (9585776) app_main: Free internal 61196 biggest block 53248 total 57148
I (9602506) ROUTE_HOOK: Received RIO
I (9602506) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9602706) ROUTE_HOOK: Received RIO
I (9602706) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9602706) ROUTE_HOOK: Received RIO
I (9602716) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9602726) ROUTE_HOOK: Received RIO
I (9602726) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9602916) ROUTE_HOOK: Received RIO
I (9602916) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9602916) ROUTE_HOOK: Received RIO
I (9602926) ROUTE_HOOK: prefix FD9D:2EFF:AAAA:1:: lifetime 1800
I (9605566) ROUTE_HOOK: Received RIO
I (9605576) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9605776) ROUTE_HOOK: Received RIO
I (9605776) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9605776) ROUTE_HOOK: Received RIO
I (9605786) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9605796) ROUTE_HOOK: Received RIO
I (9605796) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9605776) app_main: Free internal 47180 biggest block 34816 total 43132
Heap summary for capabilities 0x00000800:
At 0x3ffb2730 len 15448 free 4 allocated 14864 min_free 4
largest_free_block 0 alloc_blocks 41 free_blocks 0 total_blocks 41
At 0x3ffaff10 len 240 free 4 allocated 28 min_free 4
largest_free_block 0 alloc_blocks 2 free_blocks 0 total_blocks 2
At 0x3ffb6388 len 7288 free 4 allocated 6660 min_free 4
largest_free_block 0 alloc_blocks 61 free_blocks 0 total_blocks 61
At 0x3ffb9a20 len 16648 free 700 allocated 14740 min_free 4
largest_free_block 672 alloc_blocks 118 free_blocks 2 total_blocks 120
At 0x3ffd5710 len 43248 free 88 allocated 40976 min_free 4
largest_free_block 40 alloc_blocks 345 free_blocks 3 total_blocks 348
At 0x3ffe0440 len 15072 free 32 allocated 14572 min_free 4
largest_free_block 24 alloc_blocks 13 free_blocks 1 total_blocks 14
At 0x3ffe4350 len 113840 free 56316 allocated 56156 min_free 216
largest_free_block 53248 alloc_blocks 124 free_blocks 6 total_blocks 130
At 0x4009ee9c len 4452 free 4048 allocated 20 min_free 4016
largest_free_block 3840 alloc_blocks 1 free_blocks 1 total_blocks 2
Totals:
free 61196 allocated 148016 min_free 4256 largest_free_block 53248
I (9605976) ROUTE_HOOK: Received RIO
I (9605986) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9606186) ROUTE_HOOK: Received RIO
I (9606186) ROUTE_HOOK: prefix FD9D:2EFF:AAAA:1:: lifetime 1800
I (9625956) app_main: Free internal 61196 biggest block 53248 total 57148
I (9645956) app_main: Free internal 61196 biggest block 53248 total 57148
I (9654316) ROUTE_HOOK: Received RIO
I (9654316) ROUTE_HOOK: prefix 2600:4040:51BF:4000:: lifetime 7200
I (9665956) app_main: Free internal 61196 biggest block 53248 total 57148
I (9672336) ROUTE_HOOK: Received RIO
I (9672336) ROUTE_HOOK: prefix FD89:EBF4:10D6:: lifetime 1800
I (9685956) app_main: Free internal 61200 biggest block 53248 total 57152
E (9698666) chip[CSL]: PacketBuffer: pool EMPTY. B
Heap summary for capabilities 0x00000800:
At 0x3ffb2730 len 15448 free 4 allocated 14864 min_free 4
largest_free_block 0 alloc_blocks 41 free_blocks 0 total_blocks 41
At 0x3ffaff10 len 240 free 4 allocated 28 min_free 4
largest_free_block 0 alloc_blocks 2 free_blocks 0 total_blocks 2
At 0x3ffb6388 len 7288 free 4 allocated 6660 min_free 4
largest_free_block 0 alloc_blocks 61 free_blocks 0 total_blocks 61
At 0x3ffb9a20 len 16648 free 68 allocated 15304 min_free 4
largest_free_block 24 alloc_blocks 135 free_blocks 3 total_blocks 138
At 0x3ffd5710 len 43248 free 44 allocated 41016 min_free 4
largest_free_block 16 alloc_blocks 346 free_blocks 2 total_blocks 348
At 0x3ffe0440 len 15072 free 32 allocated 14572 min_free 4
largest_free_block 24 alloc_blocks 13 free_blocks 1 total_blocks 14
At 0x3ffe4350 len 113840 free 7504 allocated 104712 min_free 216
largest_free_block 1472 alloc_blocks 188 free_blocks 16 total_blocks 204
At 0x4009ee9c len 4452 free 4048 allocated 20 min_free 4016
largest_free_block 3840 alloc_blocks 1 free_blocks 1 total_blocks 2
Totals:
free 11708 allocated 197176 min_free 4256 largest_free_block 3840
I (9698766) chip[DIS]: mDNS broadcast full failed in 1 separate send attempts.
E (9698776) chip[DIS]: Failed to reply to query: b
I (9705956) app_main: Free internal 61196 biggest block 53248 total 57148
I (9725956) app_main: Free internal 61196 biggest block 53248 total 57148
I (9745956) app_main: Free internal 61196 biggest block 53248 total 57148
I (9748826) ROUTE_HOOK: Received RIO
I (9748836) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9749036) ROUTE_HOOK: Received RIO
I (9749036) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9749036) ROUTE_HOOK: Received RIO
I (9749046) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9749236) ROUTE_HOOK: Received RIO
I (9749236) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9749236) ROUTE_HOOK: Received RIO
I (9749246) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9749646) ROUTE_HOOK: Received RIO
I (9749646) ROUTE_HOOK: prefix FD9D:2EFF:AAAA:1:: lifetime 1800
I (9765956) app_main: Free internal 61196 biggest block 53248 total 57148
I (9785956) app_main: Free internal 61196 biggest block 53248 total 57148
I (9800236) ROUTE_HOOK: Ignore invalid ICMP packet
I (9800446) ROUTE_HOOK: Received RIO
I (9800446) ROUTE_HOOK: prefix FD85:96F1:7244:1:: lifetime 1800
I (9800446) ROUTE_HOOK: Received RIO
Possible explanation for the above trace....
There is MDNS problem. The CHIP MDNS stack quickly retries before the previous operation times out. Those retries chew up all 32 of the dynamic packet buffers causing the system to run out of memory. Later those operations time out and the packet buffers are freed.
Where did this 32 come from? It was already in my config file when I started looking at this. 32 is too high for a system without PSRAM.
This was caused by a memory leak in older versions of esp-matter. Those leaks appear to be fixed now.