[TW#24371] I2C crashes

[Sermus]

Environment

• Development Kit: ESP32-Wrover-Kit | custom hardware
• Kit version v3
• Core (if using chip or module): ESP-WROOM32|ESP32
• IDF version (git rev-parse --short HEAD to get the commit id.):
  i tried on 3.0, 3.1 and master HEAD (be81d2c)
• Development Env: make
• Operating System: MacOS
• Power Supply: USB

Problem Description

I've been facing a crash in i2c. The symptoms are exactly are similar to what is written down in #1325 which is closed for the reason i don't know.
The crash is sporadic. Several thousand i2c transactions may pass before this happen.

It crashes with the output as follows:
GGuru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC : 0x40084477 PS : 0x00050031 A0 : 0x40082330 A1 : 0x3ffb05d0
0x40084477: i2c_isr_handler_default at esp-idf/components/driver/i2c.c:998

0x40082330: _xt_lowint1 at esp-idf/components/freertos/xtensa_vectors.S:1105

A2 : 0x00000000 A3 : 0x3ffd4e74 A4 : 0x3ff0d8dc A5 : 0xfff539d0
A6 : 0x3ffd4a20 A7 : 0x00060823 A8 : 0x2011301c A9 : 0x00000001
A10 : 0x0000cdcd A11 : 0x00000002 A12 : 0x00000001 A13 : 0x000000ff
A14 : 0x00000001 A15 : 0x00060623 SAR : 0x00000016 EXCCAUSE: 0x0000001c
EXCVADDR: 0x0000002c LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0x00000000
Core 0 was running in ISR context:
EPC1 : 0x40084477 EPC2 : 0x00000000 EPC3 : 0x00000000 EPC4 : 0x00000000
0x40084477: i2c_isr_handler_default at esp-idf/components/driver/i2c.c:998

Backtrace: 0x40084477:0x3ffb05d0 0x4008232d:0x3ffb0610 0x4008c91e:0x00000000
0x40084477: i2c_isr_handler_default at esp-idf/components/driver/i2c.c:998

0x4008232d: _xt_lowint1 at esp-idf/components/freertos/xtensa_vectors.S:1105

0x4008c91e: xTaskGetTickCountFromISR at esp-idf/components/freertos/tasks.c:5112

Expected Behavior

No crashes

Actual Behavior

Crashes

Steps to repropduce

Just reading every 20ms from the i2c with the routine like this:
bool i2c::receive_bytes(uint8_t i2c_addr, char* buf, uint16_t length)
{
i2c_cmd_handle_t cmd = i2c_cmd_link_create();
esp_err_t ret = i2c_master_start(cmd);
ret = i2c_master_write_byte(cmd, ( i2c_addr << 1 ) | I2C_MASTER_READ, ACK_CHECK_EN);
assert(ret == ESP_OK);
if (length > 1)
{
ret = i2c_master_read(cmd, (uint8_t*)buf, length - 1, ACK_VAL);
assert(ret == ESP_OK);
}
ret = i2c_master_read_byte(cmd, (uint8_t*)(&buf[length - 1]), NACK_VAL);
assert(ret == ESP_OK);
ret = i2c_master_stop(cmd);
assert(ret == ESP_OK);
ret = i2c_master_cmd_begin(i2c_port, cmd, pdMS_TO_TICKS(I2C_MASTER_TIMEOUT));
i2c_cmd_link_delete(cmd);
return ret == ESP_OK;
}

// It helps if you attach a picture of your setup/wiring here.

Code to reproduce this issue

Above

Debug Logs

Above

Other items if possible

• sdkconfig.txt
• elf file in the build folder (note this may contain all the code details and symbols of your project.)
• coredump (This provides stacks of tasks.)

[Sermus]

I enabled verbose logging and found there is a pattern in the log before it crashes.

D (11345) intr_alloc: Connected src 50 to int 17 (cpu 0)
V (11345) intr_alloc: esp_intr_free: Disabling int, killing handler
V (11345) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (11345) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (11345) intr_alloc: Connected src 50 to int 17 (cpu 0)
V (11345) intr_alloc: esp_intr_free: Disabling int, killing handler
V (11345) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (11345) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (11345) intr_alloc: Connected src 50 to int 17 (cpu 0)
V (11355) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (11355) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0xE
D (11355) intr_alloc: Connected src 50 to int 3 (cpu 1)
Guru Meditation Error: Core 0 panic'ed (LoadProhibited)

Typical behavior is that the intr is always deallocated before it's allocated again.
Right before crashing the intr seems to not be deallocated, so the intr source seems to be connected on both cores.

[UncleRus]

Yes, I can confirm that the main I2C driver crashing when the task using it is not tied to a single CPU.

[koobest]

Hi, @Sermus, @UncleRus
Can you kindly provide a simple code or any suggestion to help us reproduce this problem? perhaps this problem can be reproduced in some complicated applications.

thanks !!

[Sermus]

Hello, It's reproduced in our production environment for one of the device types we develop. I can surely say there is another product which we use I2C in similar conditions (even with the same i2c slave) in and it works. So making a simple demo project which would demonstrate the issue will most likely fail. There are certain circumstances making it crash. We must prepare for a long fight in this sense. If you need any details i'll provide.

…

On Mon, Jul 23, 2018 at 11:59 AM kooho ***@***.***> wrote: Hi, @Sermus <https://github.com/Sermus>, @UncleRus <https://github.com/UncleRus> Can you kindly provide a simple code or any suggestion to help us reproduce this problem? perhaps this problem can be reproduced in some complicated applications. thanks !! — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#2211 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AD65a1we-JvS8u9Y9PJXBobF03n_Abysks5uJZBzgaJpZM4VXeoX> .

[igrr]

@Sermus It looks like the driver does not check that i2c_driver_delete is called from the same CPU as i2c_driver_install. If it happens to be called from the other CPU (say CPU1), then previously installed handler (on CPU0) will not be removed, which may cause the interrupt to be invoked when driver instance is deleted. This seems to match the stack trace you have provided (NULL pointer dereference in I2C ISR handler).

Please confirm whether you are calling i2c_driver_install and i2c_driver_delete often, and whether this may happen from a non-pinned task or from tasks pinned to different CPUs.

[Sermus]

@igrr Ivan, I confirm there were multiple install/deinstall calls and the task doing that wasn't pinned to a core. After removing this (it wasn't really necessary) i2c seems to behave properly. Thanks for the hint.
However, the driver shall include a bit of protection against such situations, I suppose.

[igrr]

Yes, of course, it should use esp_ipc_call or similar mechanism to ensure that interrupt is allocated and freed on the same core. We'll fix this.

[UncleRus]

Any news?

[costaud]

The fix will soon be in the merge queue.

[UncleRus]

Loks like this queue is very loooong

[koobest]

hi,The fix has been merged into the master. If there are still problems, please let us know.
thanks !!