Skip to content

I2c i2c_isr_handler_default cause watchdog timeout #4227

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
DamithVG opened this issue Aug 4, 2020 · 8 comments
Closed

I2c i2c_isr_handler_default cause watchdog timeout #4227

DamithVG opened this issue Aug 4, 2020 · 8 comments

Comments

@DamithVG
Copy link

DamithVG commented Aug 4, 2020 •
edited
Loading

Hardware:

Board: ESP32 Dev Module
Core Installation version: 1.0.4
IDE name: Arduino IDE
Flash Frequency: 80Mhz
PSRAM enabled: no
Upload Speed: 115200
Computer OS: Windows 10

Description:

when running a code, sometimes i2c_isr_handler_default() function executes over and over again and causes firing the interrupt watchdog. This doesn't happen periodically. Sometimes it is 2 3 hours after ESP starts and sometimes it is just 20 minutes.
According to the debug text, activeInt variable of esp32-hal-i2c.c file is 4.

When i examine the esp32-hal-i2c.c file, in line 909, i noticed that interrupts were handled in an while loop. It only exits when activeInt is 0.
Now look the if condition in line 1003.

if(activeInt) { // clear unhandled if possible?  What about Disabling interrupt?
            p_i2c->dev->int_clr.val = activeInt;
            log_e("unknown int=%x",activeInt);
            // disable unhandled IRQ,
            p_i2c->dev->int_ena.val = p_i2c->dev->int_ena.val & (~activeInt);
        }

If this condition is the only condition becomes true, the while loop never exits because activeInt will not set to 0 and ISR executes until INT WDT fires.

This is the case as i understand. Please correct me if im wrong.

Thank you.

Debug Messages:

[03/08/20 - 16:03:09:283] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:294] 

[03/08/20 - 16:03:09:294] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:304] 

[03/08/20 - 16:03:09:304] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:304] 

[03/08/20 - 16:03:09:304] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:304] 

[03/08/20 - 16:03:09:304] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:314] 

[03/08/20 - 16:03:09:314] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:323] 

[03/08/20 - 16:03:09:323] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:323] 

[03/08/20 - 16:03:09:323] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:333] 

[03/08/20 - 16:03:09:333] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:333] 

[03/08/20 - 16:03:09:333] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:344] 

[03/08/20 - 16:03:09:344] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:353] 

[03/08/20 - 16:03:09:353] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:353] 

[03/08/20 - 16:03:09:353] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:363] 

[03/08/20 - 16:03:09:363] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:363] 

[03/08/20 - 16:03:09:363] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:374] 

[03/08/20 - 16:03:09:374] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:383] 

[03/08/20 - 16:03:09:383] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:383] 

[03/08/20 - 16:03:09:383] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:393] 

[03/08/20 - 16:03:09:393] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:393] 

[03/08/20 - 16:03:09:393] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:404] 

[03/08/20 - 16:03:09:404] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:404] 

[03/08/20 - 16:03:09:404] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:414] 

[03/08/20 - 16:03:09:414] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:423] 

[03/08/20 - 16:03:09:423] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:423] 

[03/08/20 - 16:03:09:423] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:433] 

[03/08/20 - 16:03:09:433] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:433] 

[03/08/20 - 16:03:09:433] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:444] 

[03/08/20 - 16:03:09:444] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:454] 

[03/08/20 - 16:03:09:454] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:454] 

[03/08/20 - 16:03:09:454] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:463] 

[03/08/20 - 16:03:09:463] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:463] 

[03/08/20 - 16:03:09:463] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:473] 

[03/08/20 - 16:03:09:473] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:484] 

[03/08/20 - 16:03:09:484] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:484] 

[03/08/20 - 16:03:09:484] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:494] 

[03/08/20 - 16:03:09:494] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:494] 

[03/08/20 - 16:03:09:494] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:504] 

[03/08/20 - 16:03:09:504] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:513] 

[03/08/20 - 16:03:09:513] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:513] 

[03/08/20 - 16:03:09:513] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:524] 

[03/08/20 - 16:03:09:524] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:524] 

[03/08/20 - 16:03:09:524] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:533] 

[03/08/20 - 16:03:09:533] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:533] 

[03/08/20 - 16:03:09:533] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:543] 

[03/08/20 - 16:03:09:543] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:554] 

[03/08/20 - 16:03:09:554] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:554] 

[03/08/20 - 16:03:09:554] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:563] 

[03/08/20 - 16:03:09:563] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:563] 

[03/08/20 - 16:03:09:563] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:573] 

[03/08/20 - 16:03:09:573] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4
[03/08/20 - 16:03:09:583] 

[03/08/20 - 16:03:09:583] [E][esp32-hal-i2c.c:1005] i2c_isr_handler_default(): unknown int=4Guru Meditation Error: Core  1 panic'ed (Interrupt wdt timeout on CPU1)
[03/08/20 - 16:03:09:594] 

[03/08/20 - 16:03:09:594] Core 1 register dump:
[03/08/20 - 16:03:09:594] 

[03/08/20 - 16:03:09:594] PC      : 0x4000921a  PS      : 0x00060d34  A0      : 0x80007d06  A1      : 0x3ffbe640  
[03/08/20 - 16:03:09:604] 

[03/08/20 - 16:03:09:604] A2      : 0x00800000  A3      : 0x3ffbe660  A4      : 0x00000002  A5      : 0x00000010  
[03/08/20 - 16:03:09:614] 

[03/08/20 - 16:03:09:614] A6      : 0x00000002  A7      : 0x3ffbe584  A8      : 0x3ff40000  A9      : 0x0000000d  
[03/08/20 - 16:03:09:614] 

[03/08/20 - 16:03:09:614] A10     : 0x00800000  A11     : 0x3ff4001c  A12     : 0x3ffdfb20  A13     : 0x3ffdfb28  
[03/08/20 - 16:03:09:623] 

[03/08/20 - 16:03:09:623] A14     : 0x3ffdf9e5  A15     : 0x3ffdfb29  SAR     : 0x00000004  EXCCAUSE: 0x00000006  
[03/08/20 - 16:03:09:633] 

[03/08/20 - 16:03:09:633] EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffa  
[03/08/20 - 16:03:09:644] 

[03/08/20 - 16:03:09:644] Core 1 was running in ISR context:
[03/08/20 - 16:03:09:644] 

[03/08/20 - 16:03:09:644] EPC1    : 0x4000beb4  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x4000921a
[03/08/20 - 16:03:09:653] 

[03/08/20 - 16:03:09:653] 
[03/08/20 - 16:03:09:653] 

[03/08/20 - 16:03:09:653] Backtrace: 0x4000921a:0x3ffbe640 0x40007d03:0x3ffbe660 0x40007c69:0x3ffbe680 0x40008106:0x3ffbe6a0 0x400e216e:0x3ffbe730 0x40081a7a:0x3ffbe790 0x40082b11:0x3ffbe7b0 0x400850c5:0x3ffbe7d0 0x4000bfed:0x3ffb8fb0 0x4008a669:0x3ffb8fc0 0x4008c
[03/08/20 - 16:03:09:673] 3b3:0x3ffb8fe0 0x4008cb64:0x3ffb9000 0x40085368:0x3ffb9020 0x4008539d:0x3ffb9040 0x40085861:0x3ffb9060 0x4000beaf:0x3ffb9080 0x400e212d:0x3ffb90a0 0x400dbfde:0x3ffb9100 0x400dc33d:0x3ffb9220 0x400894d1:0x3ffb9250
[03/08/20 - 16:03:09:694] 

[03/08/20 - 16:03:09:694] 
[03/08/20 - 16:03:09:694] 

[03/08/20 - 16:03:09:694] Core 0 register dump:
[03/08/20 - 16:03:09:694] 

[03/08/20 - 16:03:09:694] PC      : 0x4016af06  PS      : 0x00060734  A0      : 0x800e6c21  A1      : 0x3ffbc100  
[03/08/20 - 16:03:09:704] 

[03/08/20 - 16:03:09:704] A2      : 0x00000000  A3      : 0x00000001  A4      : 0x800896e4  A5      : 0x3ffb59d0  
[03/08/20 - 16:03:09:704] 

[03/08/20 - 16:03:09:704] A6      : 0x00000000  A7      : 0x3ffbbe00  A8      : 0x800e5c62  A9      : 0x3ffbc0d0  
[03/08/20 - 16:03:09:713] 

[03/08/20 - 16:03:09:713] A10     : 0x00000000  A11     : 0x00000001  A12     : 0x800896e4  A13     : 0x3ffb55a0  
[03/08/20 - 16:03:09:723] 

[03/08/20 - 16:03:09:723] A14     : 0x00000000  A15     : 0x3ffbbe00  SAR     : 0x00000000  EXCCAUSE: 0x00000006  
[03/08/20 - 16:03:09:733] 

[03/08/20 - 16:03:09:733] EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  
[03/08/20 - 16:03:09:744] 

[03/08/20 - 16:03:09:744] 
[03/08/20 - 16:03:09:744] 

[03/08/20 - 16:03:09:744] Backtrace: 0x4016af06:0x3ffbc100 0x400e6c1e:0x3ffbc120 0x4008ace1:0x3ffbc140 0x400894d1:0x3ffbc160
[03/08/20 - 16:03:09:744] 

[03/08/20 - 16:03:09:744] 
[03/08/20 - 16:03:09:753] 

[03/08/20 - 16:03:09:753] Rebooting...
[03/08/20 - 16:03:09:753]

decoded backtrace

Decoding stack results
0x4008c417: multi_heap_free_impl at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap.c line 131
0x4008cb4e: multi_heap_get_allocated_size at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c line 290
0x40085368: heap_caps_free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/heap_caps.c line 267
0x4008539d: heap_caps_realloc at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/heap_caps.c line 282
0x40085861: lock_init_generic at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/locks.c line 85
0x400e212d: uartBegin at C:\Users\VEGA_1010\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.4\cores\esp32\esp32-hal-uart.c line 207
0x40081a7a: pinMatrixInDetach at C:\Users\VEGA_1010\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.4\cores\esp32\esp32-hal-matrix.c line 40
0x40082b11: esp_intr_enable at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp32/intr_alloc.c line 801
0x4008a669: prvAddNewTaskToReadyList at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/tasks.c line 1149
0x4008c3b3: multi_heap_malloc_impl at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap.c line 155
0x4008cb64: multi_heap_get_allocated_size at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c line 295
0x40085368: heap_caps_free at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/heap_caps.c line 267
0x4008539d: heap_caps_realloc at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/heap_caps.c line 282
0x40085861: lock_init_generic at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/locks.c line 85
0x400e212d: uartBegin at C:\Users\VEGA_1010\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.4\cores\esp32\esp32-hal-uart.c line 207
0x400dbfde: ping_start(IPAddress, int, int, int, int, ping_option*) at C:\Users\VEGA_1010\Documents\Arduino\libraries\ESP32Ping-master\ping.cpp line 121
0x400dc33d: WiFiClient::connect(char const*, unsigned short, int) at C:\Users\VEGA_1010\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.4\cores\esp32/IPAddress.h line 29
0x400894d1: xPortSysTickHandler at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/port.c line 284
@atanisoft
Copy link
Collaborator

You can't call log_e inside an isr. The backtrace points to the uart failing to transmit and not i2c at fault.

However, in the snippet you posted from i2c, the first line inside that if block will clear the interrupt and the line after the log will disable it from being raised again.

The activeInt variable should be reset by assignment inside the loop somewhere.

@DamithVG
Copy link
Author

DamithVG commented Aug 4, 2020 •
edited
Loading

You can't call log_e inside an isr. The backtrace points to the uart failing to transmit and not i2c at fault.

But int the I2c Hal.c file, theydid it. https://github.com/espressif/arduino-esp32/blob/master/cores/esp32/esp32-hal-i2c.c
And also please forgive me, i decoded part of the backtrace, now i edited it with full decode result. Seems like something related to heap.
Default Int wdt timeout is 300ms. As you can see, in the log file timestamps, Watchdog fires exactly 300ms after the i2c_isr_handler_default() execution started,

However, in the snippet you posted from i2c, the first line inside that if block will clear the interrupt and the line after the log will
disable it from being raised again.

Yes that's true, But ISR never exits.

The activeInt variable should be reset by assignment inside the loop somewhere.

Yes that should, But couldn't find a resetting line in hal i2c.c file.

@atanisoft
Copy link
Collaborator

But int the I2c Hal.c file, theydid it

Yes, I see that. It should be isr_log_e() instead.

And also please forgive me, i decoded part of the backtrace, now i edited it with full decode result. Seems like something related to heap.

The updated decode doesn't appear related to I2C but instead due to re-initialization of the UART which looks like an issue that was reported already (though I can't find it currently).

Yes that should, But couldn't find a resetting line in hal i2c.c file.

inside the if statement where the log_e call is add an assignment to set activeInt to zero. This block shouldn't ever be entered under normal circumstances though.

@DamithVG
Copy link
Author

DamithVG commented Aug 4, 2020

The updated decode doesn't appear related to I2C but instead due to re-initialization of the UART which looks like an issue that was reported already (though I can't find it currently).

If you find the issue, please post it here

inside the if statement where the log_e call is add an assignment to set activeInt to zero. This block shouldn't ever be entered under normal circumstances though.

It is a Rx FIFO overflow. Dont know what cause it. I think wire library should take care of overflows. However for some reason, if it happens INT WDT timeout is inevitable.

Thank you

@DamithVG
Copy link
Author

DamithVG commented Aug 4, 2020 •
edited
Loading

Yes, I see that. It should be isr_log_e() instead.

Is it possible that log_e cause the UART malfunction?

@atanisoft
Copy link
Collaborator

Is it possible that log_e cause the UART malfunction?

Being called inside an ISR context very likely it is not helping.

It is a Rx FIFO overflow.

that should be handled elsewhere in the ISR code I believe.

Dont know what cause it. I think wire library should take care of overflows.

Often it is a misbehaving library that uses Wire, ie it doesn't check error codes etc...

@DamithVG
Copy link
Author

DamithVG commented Aug 4, 2020

Thank you

@lbernstone
Copy link
Contributor

Fix Serial.end: #3894

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@atanisoft @lbernstone @DamithVG