idf.py coredump-debug recorded crashed at `SPILL_ALL_WINDOWS` (IDFGH-16952)

[wuyuanyi135]

sdkconfig.zip

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.5.1

Espressif SoC revision.

ESP32S3 V0.2

Operating System used.

Windows

How did you build your project?

Command line with Make

If you are using Windows, please specify command line type.

None

Development Kit.

CUSTOM BOARD

Power Supply used.

USB

What is the expected behavior?

n/a

What is the actual behavior?

I have a untethered device and I use idf.py coredump-debug to review what was crashing. This time I captured a weird coredump with

warning: could not convert 'main' from the host encoding (CP1252) to UTF-32.
This normally should not happen, please file a bug report.
#0  _xt_context_save () at C:/Espressif/frameworks/esp-idf-v5.5/components/xtensa\xtensa_context.S:203
203         SPILL_ALL_WINDOWS                  /* place the live register windows there */
[Current thread is 1 (process 1070345744)]
(gdb) bt
Python Exception <class 'gdb.error'>: failed to find previous frame when computing inline frame id
#0  _xt_context_save () at C:/Espressif/frameworks/esp-idf-v5.5/components/xtensa\xtensa_context.S:203
(gdb) t
[Current thread is 1 (process 1070345744)]

There is no useful stacktrace for finding locating the crash. I could add that the crash only happen occasionally when a computer is trying to disconnect from the tinyusb cdc console. To me I think not able to finding the reason from stacktrace is a more serious problem.

Can you please explain what SPILL_ALL_WINDOWS is and what could cause this?

Steps to reproduce.

Please contact me for the elf and coredump if necessary.

Debug Logs.

Diagnostic report archive.

No response

More Information.

sdkconfig.zip

[erhankur]

@wuyuanyi135 Do you see the issue with the seperate coredump stack? Could you attach your sdkconfig please?

We have a fix in the master branch. c9bee75

But not yet backported to v5.5 . I will create a backport and send you a patch to try.

[erhankur]

Ok I didn't see you already attached. I will check it.

[wuyuanyi135]

@wuyuanyi135 Do you see the issue with the seperate coredump stack? Could you attach your sdkconfig please?

We have a fix in the master branch. c9bee75

But not yet backported to v5.5 . I will create a backport and send you a patch to try.

The other coredumps work just fine. If you would need the elf and coredump I could prepare after a while.

[erhankur]

Please enable CONFIG_ESP_COREDUMP_CAPTURE_DRAM and save .bss, .data and heap data to the coredump. Then you can send me the elf and coredump file.

[wuyuanyi135]

@erhankur Hi, I enabled CONFIG_ESP_COREDUMP_CAPTURE_DRAM just now and noticed that the coredump was no longer written anymore.

PS C:\Users\wuyua\CLionProjects\UniLAB\projects\project_unilab_drive> idf.py coredump-debug
Executing action: coredump-debug
Serial port COM7
Connecting...
Detecting chip type... ESP32-S3
WARNING:root:The core dump image offset is not specified. Use partition offset: 0x369000.
ERROR:root:Incorrect size of core dump image: 4294967295, use partition size instead: 393216
Failed to load core dump: Core dump version "0xffff" is not supported!

I could confirm that without CONFIG_ESP_COREDUMP_CAPTURE_DRAM the coredump was written. Otherwise it should have complained about the APP hash inconsistency

[erhankur]

It requires more flash partition according to your application. All .bss, .data and heap will be saved. So please increase coredump partition to the safe value and try again.

[wuyuanyi135]

@erhankur Thanks for the tips, it works now. Can I send you the dumps and elf privately?

[wuyuanyi135]

Hello @erhankur, I removed the sensitive part of the code. please see the attached coredump and elf.

dump.zip

[wuyuanyi135]

@erhankur
After bisecting the code, I located the error was at

void BaseObservable::enable_push_model(bool enable, Duration interval) {
  if (!enable) {
    // 禁用推送
    push_model_enabled = false;
  } else {
    push_interval = interval;
    push_model_enabled = true;
    LI("数据自动推送生效，间隔 {}", interval);  <--------- CRASHING 

    if (!push_model_thread.joinable()) {
      push_model_thread = std::thread([]() {
        while (true) {
          if (!push_model_enabled) {
            vTaskDelay(pdMS_TO_TICKS(1000));
            continue;
          }

          ..........

The LI macro is basically an encapsulated ESP_LOGI with the power of fmt::format.
The Duration was std::chrono::system_clock::duration

I have several observations after playing around:

1. Removing all chinese characters, leaving LI("{}", interval);, no crash
2. Putting some ascii characters, LI("even though this line will be extremely long it does not crash {}", interval);, no crash
3. Keeping the chinese character, removing chrono variable format (LI("数据自动推送生效，间隔");), no crash
4. replacing this line as fmt::format("数据自动推送生效，间隔 {}", interval), no crash
5. fmt::vformat("数据自动推送生效，间隔 {}", fmt::make_format_args(interval)); no crash
6. replacing the duration to some other types like integer LI("数据自动推送生效，间隔 {}", 112233);, no crash
7. calling LI("数据自动推送生效，间隔 {}", interval); somewhere else with the same input, no crash
8. enlarge the stack size (4k, 8k), no effect on crash or not

My conclusions:

1. The fmt library was not the root cause
2. The logging was the cause of crash.
3. The length of the logging line is not the cause of crash
4. The only crash combination was due to logging a line with std::chrono::system_clock::duration as format argument.
5. From my experience, this weird crash usually caused by stackoverflow that led to memory smudge. In this case assigning larger stack size did not help.

@erhankur Could you provide some insights from the coredump?

[erhankur]

@wuyuanyi135 sorry for my late response.

Please correct me if I'm missing something.

From the coredump;

1. First exception happened inside esp_psram_check_ptr_addr()

epc1 = 0x403763eb points at:

l32r a8, ... (3fca9168 <s_psram_ctx>)

That l32r loads the address of s_psram_ctx into a8. The next instructions read fields from it.

If s_psram_ctx is invalid / not accessible right now, the following loads will fault.

2. While handling that exception, a second exception happened during context save

The current pc is inside _xt_context_save (where ESP-IDF forces SPILL_ALL_WINDOWS / register window spilling). rotw itself doesn't store anything, but it forces the CPU to spill register windows to the current stack.

If the stack pointer / save area is already corrupted, points to an invalid region, or the spill path touches memory that is not accessible in the current context, the spill/store will fault again. This is consistent with:

• exccause = DoubleException (an exception occurred while already handling another exception)
• excvaddr = 0xfffffff4 (bogus store address, typically “near NULL”, often caused by a bad base register during the save/spill)

Can you check whether the pointer being tested in esp_psram_check_ptr_addr() (argument in a2) is valid at that moment (not poisoned like 0xA5A5A5A5, not freed), and whether s_psram_ctx contents (enabled + PSRAM range fields) are stable/non-corrupted right before the crash?

During USB disconnect, some callback/path in the TinyUSB task might be touching memory that’s not safe in that moment or is already freed/corrupted.

[wuyuanyi135]

@erhankur No problem, thanks for taking time into this. I do not have explicit invocation on esp_psram_check_ptr_addr. The only thing I could relate between this issue and the phenomena is that the LI will write the new logging line into a circular buffer inside PSRAM. Otherwise I don't see any PSRAM interaction in this segment of code. Could you please suggest what could be done to furthur investigate the issue?