Skip to content
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.

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

esp32 hangs in intr_alloc.c ( portEXIT_CRITICAL(&spinlock); ) (IDF-188) #1981

Closed
PhilColbert opened this issue May 21, 2018 · 11 comments
Closed
Assignees

Comments

@PhilColbert
Copy link

PhilColbert commented May 21, 2018

After installing the new espidf and arduino component, Serial 1 ( serial 2 ) randomly hangs on boot.

I have traced it to the last portEXIT_CRITICAL(&spinlock); call in function esp_err_t esp_intr_alloc_intrstatus in intr_alloc.c

80% of the time this works, 20% of the time the system just stops and hangs there.

There is a gps currently attached to the port and continuously feeding serial data into it if thats relevant.

Any ideas ?

Just a very simple program hangs 20% of the time., I know this is arduino but it hangs in the espidf code.

#include <Arduino.h>

#include "esp_log.h"

HardwareSerial GPSSerial(1);

void setup()
{
esp_log_level_set("*", ESP_LOG_VERBOSE);
Serial.begin(115200);
Serial.println("start");
GPSSerial.begin(9600, (uint32_t) SERIAL_8N1,33,(int8_t) 22);

}

void loop()
{
delay(1000);
Serial.println("running");
}

I have tried different setups, with and without the GPS attached and it randomly stops at the same place.

this never happened with the older ESPIDF code.

v3.1-dev-439-g37765d00-dirty - no hangs

v3.1-dev-858-gf885e8b8-dirty - hanging.

@PhilColbert
Copy link
Author

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5648
ho 0 tail 12 room 4
load:0x40078000,len:0
load:0x40078000,len:14008
entry 0x4007860c
[1B][0;32mI (30) boot: ESP-IDF v3.1-dev-858-gf885e8b8-dirty 2nd stage bootloader[1B][0m
[1B][0;32mI (30) boot: compile time 13:25:32[1B][0m
[1B][0;32mI (31) boot: Enabling RNG early entropy source...[1B][0m
[1B][0;32mI (36) boot: SPI Speed : 40MHz[1B][0m
[1B][0;32mI (41) boot: SPI Mode : DIO[1B][0m
[1B][0;32mI (45) boot: SPI Flash Size : 4MB[1B][0m
[1B][0;32mI (49) boot: Partition Table:[1B][0m
[1B][0;32mI (52) boot: ## Label Usage Type ST Offset Length[1B][0m
[1B][0;32mI (59) boot: 0 nvs WiFi data 01 02 00009000 00005000[1B][0m
[1B][0;32mI (67) boot: 1 otadata OTA data 01 00 0000e000 00002000[1B][0m
[1B][0;32mI (74) boot: 2 app0 OTA app 00 10 00010000 00140000[1B][0m
[1B][0;32mI (82) boot: 3 app1 OTA app 00 11 00150000 00140000[1B][0m
[1B][0;32mI (89) boot: 4 eeprom Unknown data 01 99 00290000 00001000[1B][0m
[1B][0;32mI (97) boot: 5 spiffs Unknown data 01 82 00291000 0016f000[1B][0m
[1B][0;32mI (104) boot: End of partition table[1B][0m
[1B][0;32mI (109) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x07c30 ( 31792) map[1B][0m
[1B][0;32mI (129) esp_image: segment 1: paddr=0x00017c58 vaddr=0x3ffb0000 size=0x022b4 ( 8884) load[1B][0m
[1B][0;32mI (132) esp_image: segment 2: paddr=0x00019f14 vaddr=0x40080000 size=0x00400 ( 1024) load[1B][0m
[1B][0;32mI (138) esp_image: segment 3: paddr=0x0001a31c vaddr=0x40080400 size=0x05cf4 ( 23796) load[1B][0m
[1B][0;32mI (156) esp_image: segment 4: paddr=0x00020018 vaddr=0x400d0018 size=0x164b8 ( 91320) map[1B][0m
[1B][0;32mI (189) esp_image: segment 5: paddr=0x000364d8 vaddr=0x400860f4 size=0x03250 ( 12880) load[1B][0m
[1B][0;32mI (194) esp_image: segment 6: paddr=0x00039730 vaddr=0x400c0000 size=0x00000 ( 0) load[1B][0m
[1B][0;32mI (201) boot: Loaded app from partition at offset 0x10000[1B][0m
[1B][0;32mI (201) boot: Disabling RNG early entropy source...[1B][0m
[1B][0;32mI (207) cpu_start: Pro cpu up.[1B][0m
[1B][0;32mI (211) cpu_start: Starting app cpu, entry point is 0x40080e9c[1B][0m
[1B][0;32mI (0) cpu_start: App cpu up.[1B][0m
[1B][0;32mI (221) heap_init: Initializing. RAM available for dynamic allocation:[1B][0m
D (228) heap_init: New heap initialised at 0x3ffae6e0[1B][0m
[1B][0;32mI (233) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM[1B][0m
D (239) heap_init: New heap initialised at 0x3ffb2c48[1B][0m
[1B][0;32mI (244) heap_init: At 3FFB2C48 len 0002D3B8 (180 KiB): DRAM[1B][0m
[1B][0;32mI (251) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM[1B][0m
[1B][0;32mI (257) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[1B][0m
D (263) heap_init: New heap initialised at 0x40089344[1B][0m
[1B][0;32mI (268) heap_init: At 40089344 len 00016CBC (91 KiB): IRAM[1B][0m
[1B][0;32mI (275) cpu_start: Pro cpu start user code[1B][0m
D (287) clk: RTC_SLOW_CLK calibration value: 3069530[1B][0m
V (296) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (296) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE[1B][0m
D (333) intr_alloc: Trying to connect src 46 to int 2 (cpu 0)[1B][0m
D (339) intr_alloc: After spinlock Connected src 46 to int 2 (cpu 0)[1B][0m
D (345) intr_alloc: Connected src 46 to int 2 (cpu 0)[1B][0m
V (351) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (357) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC0E[1B][0m
D (398) intr_alloc: Trying to connect src 57 to int 3 (cpu 0)[1B][0m
D (404) intr_alloc: After spinlock Connected src 57 to int 3 (cpu 0)[1B][0m
D (410) intr_alloc: Connected src 57 to int 3 (cpu 0)[1B][0m
V (416) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (422) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E[1B][0m
D (463) intr_alloc: Trying to connect src 24 to int 9 (cpu 0)[1B][0m
D (469) intr_alloc: After spinlock Connected src 24 to int 9 (cpu 0)[1B][0m
D (475) intr_alloc: Connected src 24 to int 9 (cpu 0)[1B][0m
[1B][0;32mI (481) cpu_start: Starting scheduler on PRO CPU.[1B][0m
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
D (40) intr_alloc: Trying to connect src 25 to int 2 (cpu 1)[1B][0m
D (50) intr_alloc: After spinlock Connected src 25 to int 2 (cpu 1)[1B][0m
D (50) intr_alloc: Connected src 25 to int 2 (cpu 1)[1B][0m
[1B][0;32mI (60) cpu_start: Starting scheduler on APP CPU.[1B][0m
D (615) heap_init: New heap initialised at 0x3ffe0440[1B][0m
D (625) heap_init: New heap initialised at 0x3ffe4350[1B][0m
V (625) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (625) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE[1B][0m
D (625) intr_alloc: Connected src 16 to int 12 (cpu 0)[1B][0m
D (695) nvs: nvs_flash_init_custom partition=nvs start=9 count=5[1B][0m
V (785) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (785) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
D (845) intr_alloc: Connected src 34 to int 3 (cpu 1)[1B][0m
start
V (865) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (865) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
D (905) intr_alloc: Trying to connect src 36 to int 4 (cpu 1)[1B][0m
Task watchdog got triggered. The following tasks did not reset the watchdog in time:

  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask

@PhilColbert
Copy link
Author

PhilColbert commented May 22, 2018

Ok, found some more info on this, perhaps the issue or problem - please can someone test?!

Spent this morning, completely installing the latest IDF, Arduino , everything new.

If CONFIG_LOG_DEFAULT_LEVEL is set to NONE then there is no hanging.

as soon as

CONFIG_LOG_DEFAULT_LEVEL is set to VERBOSE the esp32 will hang and freeze about 20% of the time as per the above log output.

Any ideas?

Thanks

@igrr
Copy link
Member

igrr commented May 22, 2018

@PhilColbert I couldn't reproduce the issue with latest IDF when using Arduino as a component. Could you please attach your sdkconfig file? Thanks.

@PhilColbert
Copy link
Author

PhilColbert commented May 22, 2018

Thanks for the reply, hope its not something I am doing wrong, but its suddenly started with the new IDF code.

Try reseting it a few times, sometimes its one in 10 or less.... but it does hang :(

Standard SDK from one of the examples.

#include <Arduino.h>

#include "esp_log.h"

HardwareSerial GPSSerial(2);

void setup()
{
esp_log_level_set("*", ESP_LOG_VERBOSE);
Serial.begin(115200);
Serial.println("start");
GPSSerial.begin(9600, (uint32_t) SERIAL_8N1,33,(int8_t) 22);

}

void loop()
{

delay(1000);
Serial.println("running");

if ( millis()>3000)
{
esp_restart();
}

}

I have tried on heltec, ttgo and doit esp boards and the same.

sdkconfig.zip

@igrr
Copy link
Member

igrr commented May 22, 2018

Hi @PhilColbert I see from the log you have provided that you might be using a different sketch from the one you have provided in the first post. The log indicates that your code is using UART2 (interrupt source 36) but the code actually refers to UART1 (in the HardwareSerial constructor). Can you please check what the actual code is? FWIW, even with your attached sdkconfig I couldn't reproduced the issue after 40 or so resets.

@PhilColbert
Copy link
Author

PhilColbert commented May 22, 2018

It does the same on UART1 or 2, so does not matter which.

Thanks for trying - not sure how to proceed from here then , i will just have to run without Logs for now.

Just noticed that sdk I had set the log back to no log output, that was the one that worked in the end, sorry about that, really busy day ! That sdkconfig file will work as theres no logging.

Attached is the sdkconfig file that doesnt work ( Verbose Logging )

sdkconfig.zip

Heres the log output -

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5676
load:0x40078000,len:0
load:0x40078000,len:15356
entry 0x4007862c
[1B][0;32mI (28) boot: ESP-IDF v3.1-dev-1130-g92c469b5 2nd stage bootloader[1B][0m
[1B][0;32mI (29) boot: compile time 15:13:59[1B][0m
[1B][0;32mI (29) boot: Enabling RNG early entropy source...[1B][0m
[1B][0;32mI (35) boot: SPI Speed : 40MHz[1B][0m
[1B][0;32mI (39) boot: SPI Mode : DIO[1B][0m
[1B][0;32mI (43) boot: SPI Flash Size : 4MB[1B][0m
[1B][0;32mI (47) boot: Partition Table:[1B][0m
[1B][0;32mI (51) boot: ## Label Usage Type ST Offset Length[1B][0m
[1B][0;32mI (58) boot: 0 nvs WiFi data 01 02 00009000 00005000[1B][0m
[1B][0;32mI (65) boot: 1 otadata OTA data 01 00 0000e000 00002000[1B][0m
[1B][0;32mI (73) boot: 2 app0 OTA app 00 10 00010000 00140000[1B][0m
[1B][0;32mI (80) boot: 3 app1 OTA app 00 11 00150000 00140000[1B][0m
[1B][0;32mI (88) boot: 4 eeprom Unknown data 01 99 00290000 00001000[1B][0m
[1B][0;32mI (95) boot: 5 spiffs Unknown data 01 82 00291000 0016f000[1B][0m
[1B][0;32mI (103) boot: End of partition table[1B][0m
[1B][0;32mI (107) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x07cb8 ( 31928) map[1B][0m
[1B][0;32mI (127) esp_image: segment 1: paddr=0x00017ce0 vaddr=0x3ffb0000 size=0x023a0 ( 9120) load[1B][0m
[1B][0;32mI (131) esp_image: segment 2: paddr=0x0001a088 vaddr=0x40080000 size=0x00400 ( 1024) load[1B][0m
[1B][0;32mI (136) esp_image: segment 3: paddr=0x0001a490 vaddr=0x40080400 size=0x05b80 ( 23424) load[1B][0m
[1B][0;32mI (155) esp_image: segment 4: paddr=0x00020018 vaddr=0x400d0018 size=0x16a24 ( 92708) map[1B][0m
[1B][0;32mI (187) esp_image: segment 5: paddr=0x00036a44 vaddr=0x40085f80 size=0x03550 ( 13648) load[1B][0m
[1B][0;32mI (193) esp_image: segment 6: paddr=0x00039f9c vaddr=0x400c0000 size=0x00000 ( 0) load[1B][0m
[1B][0;32mI (200) boot: Loaded app from partition at offset 0x10000[1B][0m
[1B][0;32mI (200) boot: Disabling RNG early entropy source...[1B][0m
[1B][0;32mI (206) cpu_start: Pro cpu up.[1B][0m
[1B][0;32mI (209) cpu_start: Starting app cpu, entry point is 0x40080ea4[1B][0m
[1B][0;32mI (202) cpu_start: App cpu up.[1B][0m
[1B][0;32mI (220) heap_init: Initializing. RAM available for dynamic allocation:[1B][0m
D (227) heap_init: New heap initialised at 0x3ffae6e0[1B][0m
[1B][0;32mI (232) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM[1B][0m
D (238) heap_init: New heap initialised at 0x3ffb3578[1B][0m
[1B][0;32mI (243) heap_init: At 3FFB3578 len 0002CA88 (178 KiB): DRAM[1B][0m
[1B][0;32mI (249) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM[1B][0m
[1B][0;32mI (256) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[1B][0m
D (262) heap_init: New heap initialised at 0x400894d0[1B][0m
[1B][0;32mI (267) heap_init: At 400894D0 len 00016B30 (90 KiB): IRAM[1B][0m
[1B][0;32mI (274) cpu_start: Pro cpu start user code[1B][0m
D (286) clk: RTC_SLOW_CLK calibration value: 3062566[1B][0m
V (295) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (295) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE[1B][0m
D (300) intr_alloc: Connected src 46 to int 2 (cpu 0)[1B][0m
V (306) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (311) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC0E[1B][0m
D (320) intr_alloc: Connected src 57 to int 3 (cpu 0)[1B][0m
V (325) esp_dbg_stubs: esp_dbg_stubs_init stubs 3ffb2be0[1B][0m
V (330) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (336) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E[1B][0m
D (345) intr_alloc: Connected src 24 to int 9 (cpu 0)[1B][0m
[1B][0;32mI (350) cpu_start: Starting scheduler on PRO CPU.[1B][0m
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
D (10) intr_alloc: Connected src 25 to int 2 (cpu 1)[1B][0m
[1B][0;32mI (10) cpu_start: Starting scheduler on APP CPU.[1B][0m
D (399) heap_init: New heap initialised at 0x3ffe0440[1B][0m
D (399) heap_init: New heap initialised at 0x3ffe4350[1B][0m
V (409) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (409) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE[1B][0m
D (409) intr_alloc: Connected src 16 to int 12 (cpu 0)[1B][0m
D (429) nvs: nvs_flash_init_custom partition=nvs start=9 count=5[1B][0m
V (489) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (489) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
D (489) intr_alloc: Connected src 34 to int 3 (cpu 1)[1B][0m
start
V (499) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (509) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
Task watchdog got triggered. The following tasks did not reset the watchdog in time:

  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:
    CPU 0: IDLE
    CPU 1: loopTask
    Task watchdog got triggered. The following tasks did not reset the watchdog in time:
  • IDLE (CPU 1)
    Tasks currently running:

And then press the reset button and it works -

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5676
load:0x40078000,len:0
load:0x40078000,len:15356
entry 0x4007862c
[1B][0;32mI (28) boot: ESP-IDF v3.1-dev-1130-g92c469b5 2nd stage bootloader[1B][0m
[1B][0;32mI (29) boot: compile time 15:13:59[1B][0m
[1B][0;32mI (29) boot: Enabling RNG early entropy source...[1B][0m
[1B][0;32mI (35) boot: SPI Speed : 40MHz[1B][0m
[1B][0;32mI (39) boot: SPI Mode : DIO[1B][0m
[1B][0;32mI (43) boot: SPI Flash Size : 4MB[1B][0m
[1B][0;32mI (47) boot: Partition Table:[1B][0m
[1B][0;32mI (51) boot: ## Label Usage Type ST Offset Length[1B][0m
[1B][0;32mI (58) boot: 0 nvs WiFi data 01 02 00009000 00005000[1B][0m
[1B][0;32mI (65) boot: 1 otadata OTA data 01 00 0000e000 00002000[1B][0m
[1B][0;32mI (73) boot: 2 app0 OTA app 00 10 00010000 00140000[1B][0m
[1B][0;32mI (80) boot: 3 app1 OTA app 00 11 00150000 00140000[1B][0m
[1B][0;32mI (88) boot: 4 eeprom Unknown data 01 99 00290000 00001000[1B][0m
[1B][0;32mI (95) boot: 5 spiffs Unknown data 01 82 00291000 0016f000[1B][0m
[1B][0;32mI (103) boot: End of partition table[1B][0m
[1B][0;32mI (107) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x07cb8 ( 31928) map[1B][0m
[1B][0;32mI (127) esp_image: segment 1: paddr=0x00017ce0 vaddr=0x3ffb0000 size=0x023a0 ( 9120) load[1B][0m
[1B][0;32mI (131) esp_image: segment 2: paddr=0x0001a088 vaddr=0x40080000 size=0x00400 ( 1024) load[1B][0m
[1B][0;32mI (136) esp_image: segment 3: paddr=0x0001a490 vaddr=0x40080400 size=0x05b80 ( 23424) load[1B][0m
[1B][0;32mI (155) esp_image: segment 4: paddr=0x00020018 vaddr=0x400d0018 size=0x16a24 ( 92708) map[1B][0m
[1B][0;32mI (187) esp_image: segment 5: paddr=0x00036a44 vaddr=0x40085f80 size=0x03550 ( 13648) load[1B][0m
[1B][0;32mI (193) esp_image: segment 6: paddr=0x00039f9c vaddr=0x400c0000 size=0x00000 ( 0) load[1B][0m
[1B][0;32mI (200) boot: Loaded app from partition at offset 0x10000[1B][0m
[1B][0;32mI (200) boot: Disabling RNG early entropy source...[1B][0m
[1B][0;32mI (206) cpu_start: Pro cpu up.[1B][0m
[1B][0;32mI (209) cpu_start: Starting app cpu, entry point is 0x40080ea4[1B][0m
[1B][0;32mI (202) cpu_start: App cpu up.[1B][0m
[1B][0;32mI (220) heap_init: Initializing. RAM available for dynamic allocation:[1B][0m
D (227) heap_init: New heap initialised at 0x3ffae6e0[1B][0m
[1B][0;32mI (232) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM[1B][0m
D (238) heap_init: New heap initialised at 0x3ffb3578[1B][0m
[1B][0;32mI (243) heap_init: At 3FFB3578 len 0002CA88 (178 KiB): DRAM[1B][0m
[1B][0;32mI (249) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM[1B][0m
[1B][0;32mI (256) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[1B][0m
D (262) heap_init: New heap initialised at 0x400894d0[1B][0m
[1B][0;32mI (267) heap_init: At 400894D0 len 00016B30 (90 KiB): IRAM[1B][0m
[1B][0;32mI (274) cpu_start: Pro cpu start user code[1B][0m
D (286) clk: RTC_SLOW_CLK calibration value: 3080346[1B][0m
V (295) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (295) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE[1B][0m
D (300) intr_alloc: Connected src 46 to int 2 (cpu 0)[1B][0m
V (306) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (311) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC0E[1B][0m
D (320) intr_alloc: Connected src 57 to int 3 (cpu 0)[1B][0m
V (325) esp_dbg_stubs: esp_dbg_stubs_init stubs 3ffb2be0[1B][0m
V (330) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (336) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E[1B][0m
D (345) intr_alloc: Connected src 24 to int 9 (cpu 0)[1B][0m
[1B][0;32mI (350) cpu_start: Starting scheduler on PRO CPU.[1B][0m
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
D (10) intr_alloc: Connected src 25 to int 2 (cpu 1)[1B][0m
[1B][0;32mI (10) cpu_start: Starting scheduler on APP CPU.[1B][0m
D (399) heap_init: New heap initialised at 0x3ffe0440[1B][0m
D (399) heap_init: New heap initialised at 0x3ffe4350[1B][0m
V (409) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args[1B][0m
V (409) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE[1B][0m
D (409) intr_alloc: Connected src 16 to int 12 (cpu 0)[1B][0m
D (429) nvs: nvs_flash_init_custom partition=nvs start=9 count=5[1B][0m
V (489) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (489) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
D (489) intr_alloc: Connected src 34 to int 3 (cpu 1)[1B][0m
start
V (499) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args[1B][0m
V (509) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E[1B][0m
D (509) intr_alloc: Connected src 36 to int 4 (cpu 1)[1B][0m
running
running
running

code is
#include <Arduino.h>

#include "esp_log.h"

HardwareSerial GPSSerial(2);

void setup()
{
esp_log_level_set("*", ESP_LOG_VERBOSE);
Serial.begin(115200);
Serial.println("start");
GPSSerial.begin(9600, (uint32_t) SERIAL_8N1,33,(int8_t) 22);

}

void loop()
{

delay(1000);
Serial.println("running");

if ( millis()>3000)
{
esp_restart();
}
}

@igrr
Copy link
Member

igrr commented May 23, 2018

Do you have anything connected to UART2 (or UART1) when the issue happens? I.e. is there any data coming in? If you disconnect the thing that sends data, do you still observe the issue?

@PhilColbert
Copy link
Author

Hi, I thought I had tested it with and without a GPS attached, but seems I didnt do this properly.

If the GPS isnt connected then it works fine, no hangs, but when theres a gps connected it hangs randomly, something to do with data in the buffer perhaps , tried 2 different gps units and its the same.

Dont worry I can set logs to off and it works ok now :)

Thanks

@igrr
Copy link
Member

igrr commented May 23, 2018

That makes things slightly more clear @PhilColbert. I think this may be a genuine issue. The hint that we need to feed some data into UART will probably help us reproduce this!

@PhilColbert
Copy link
Author

Thanks for testing, sorry for not giving you better description at the start.

Where I found the hang is detailed in the first post if that helps.

Doesnt happen on serial 0 however.

I have a project where theres probably 200 people using esp32 to use as a flying instrument and this hasnt happened before I added the new codebase.

Thanks

@FayeY FayeY changed the title esp32 hangs in intr_alloc.c ( portEXIT_CRITICAL(&spinlock); ) [TW#22885] esp32 hangs in intr_alloc.c ( portEXIT_CRITICAL(&spinlock); ) May 28, 2018
@Dazza0 Dazza0 self-assigned this Oct 10, 2018
@projectgus projectgus changed the title [TW#22885] esp32 hangs in intr_alloc.c ( portEXIT_CRITICAL(&spinlock); ) esp32 hangs in intr_alloc.c ( portEXIT_CRITICAL(&spinlock); ) (IDF-188) Mar 12, 2019
@Dazza0
Copy link
Contributor

Dazza0 commented Jul 31, 2019

Hi @PhilColbert,
I think we may have narrowed down the cause of this issue. The reason why the Task WDT is triggering is due to the compounding effects of the following two issues:

  • UART peripheral not being reset after a chip restart. I.e. the UART peripheral may still assert its interrupt line event after a chip restart
  • If an interrupt is not cleared, there is a possibility that the ESP32 will loop endlessly to process the interrupt whilst still being able to feed the interrupt watchdog (thus why the task watchdog triggers instead)

Basically, what could be happening is the following series of events.

  1. Your application could initially run without issue and sets up UART2. Then maybe the application some software error and calls esp_restart(). This will restart both CPUs but most of the peripherals (including UART1 and 2) are not reset. Therefore, if it receives any further messages, it may try to assert its interrupt line to the CPU and the line will remain asserted until it is cleared by the CPU (via a register write).

  2. The CPU comes out of reset but is not interrupted by the asserted interrupt line of UART2 because the CPU has masked most of its interrupt. The CPU will unmask a particular interrupt when esp_intr_alloc_intrstatus() is called. Therefore, as soon as the critical section exits in esp_intr_alloc_intrstatus(), the CPU is interrupt by UART2.

  3. The CPU will immediately handle enter an ISR due to the asserted interrupt line for UART2, however, since the driver has not properly initialized, the handler will not do the necessary register write to UART2 such that the interrupt line is deasserted. Therefore, the CPU be stuck in a loop continuously entering, exiting, then reentering the ISR.

  4. The interrupt watchdog is not triggered because the UART2 ISR enters, does not clear the UART2 interrupt register, and exits. Therefore, the FreeRTOS tick interrupt (which feeds the Interrupt watchdog) is still able to run. The CPU will loop continuously handling interrupts until the task watchdog is triggered.

Could you please try adding the following to your setup() code to check if the theory is correct. This code will reset the UART2 peripheral.

#include "driver/periph_ctrl.h"

void setup()
{
    periph_module_reset(PERIPH_UART2_MODULE);
}

@igrr igrr closed this as completed in c082d13 Aug 27, 2019
igrr pushed a commit that referenced this issue Sep 16, 2019
This commit prevents infinite restarts caused due to an interrupt flag
was left uncleared.

Closes: #1981

Closes: IDF-188
igrr pushed a commit that referenced this issue Oct 18, 2019
This commit prevents infinite restarts caused due to an interrupt flag
was left uncleared.

Closes: #1981

Closes: IDF-188
igrr pushed a commit that referenced this issue Oct 18, 2019
This commit prevents infinite restarts caused due to an interrupt flag
was left uncleared.

Closes: #1981

Closes: IDF-188
espressif-bot pushed a commit that referenced this issue Dec 10, 2019
This commit prevents infinite restarts caused due to an interrupt flag
was left uncleared.

Closes: #1981

Closes: IDF-188
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants