franz-ms-muc
commented
1 year ago thanks @RilabsAutomotive for raising this Issue.
do we have a Minimal Example to test it ?
Open MartinPatarinski opened 1 year ago
franz-ms-muc
commented
1 year ago thanks @RilabsAutomotive for raising this Issue.
do we have a Minimal Example to test it ?
MartinPatarinski
commented
1 year ago No, we don't have currently such SW application
david-cermak
commented
1 year ago @RilabsAutomotive Could you please apply this patch to the modem sources?
diff --git a/components/esp_modem/src/esp_modem_uart.cpp b/components/esp_modem/src/esp_modem_uart.cpp
index e082473..783a5be 100644
--- a/components/esp_modem/src/esp_modem_uart.cpp
+++ b/components/esp_modem/src/esp_modem_uart.cpp
@@ -64,6 +64,7 @@ public:
void set_read_cb(std::function<bool(uint8_t *data, size_t len)> f) override
{
+ Scoped<Lock> lock(on_read_guard);
ESP_MODEM_THROW_IF_FALSE(signal.wait(TASK_PARAMS, 1000), "Failed to set UART task params");
on_read = std::move(f);
}
@@ -97,6 +98,7 @@ private:
uart_resource uart;
SignalGroup signal;
uart_task task_handle;
+ Lock on_read_guard;
};
std::unique_ptr<Terminal> create_uart_terminal(const esp_modem_dte_config *config)
@@ -120,6 +122,7 @@ void UartTerminal::task()
while (signal.is_any(TASK_START)) {
signal.set(TASK_PARAMS);
if (get_event(event, 100)) {
+ Scoped<Lock> lock(on_read_guard);
signal.clear(TASK_PARAMS);
switch (event.type) {
case UART_DATA:Could you please try to test it with this additional mutex? It seems like a race condition between the uart-task and DTE's command parser, based on the log. I just wanted to see if that was the case. Thanks!
MartinPatarinski
commented
1 year ago I think that it does not solve the problem. Here is the log:
Modem is started
....
I (00:00:52.370) esp-netif_lwip-ppp: Connected
I (00:00:52.370) ESPmodem_Cmux: ~~~~~~
I (00:00:52.375) ESPmodem_Cmux: IP : 100.82.79.105
I (00:00:52.381) ESPmodem_Cmux: Netmask : 255.255.255.255
I (00:00:52.388) ESPmodem_Cmux: Gateway : 10.64.64.64
I (00:00:52.394) ESPmodem_Cmux: Name Server1: 217.14.160.130
I (00:00:52.400) ESPmodem_Cmux: Name Server2: 217.14.164.35
I (00:00:52.406) ESPmodem_Cmux: ~~~~~~
I (00:00:52.411) ESPmodem_Cmux: GOT ip event!!!
I (00:00:52.417) esp_modem_netif: PPP state changed event 0
} (00:00:52.418) command_lib: Command: {AT+CBC
I (00:00:52.423) ESPmodem_Cmux: PPP state changed. Event PPP_PHASE_RUNNING, id: 266
I (00:00:52.423) ResourceManager: ++ connection to the Internet established
I (00:00:52.445) ResourceManager: ++ RESOURCE_INTERNET changed state: from RESOURCE_STATE_CONNECTING to RESOURCE_STATE_STARTED with target state: RESOURCE_TARGET_STATE_STARTED
} (00:00:52.449) command_lib: Token: {
} (00:00:52.449) command_lib: Command: {AT+CSQ
I (00:00:52.464) command_lib: Token: {+CBC: 0,95,4243}
} (00:00:52.475) command_lib: Token: {
I (00:00:52.480) cGuru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump: PC : 0x4038375d PS : 0x00060430 A0 : 0x8205bf3c A1 : 0x3fcae470 0x4038375d: xQueueGiveMutexRecursive at C:/Espressif/frameworks/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:676
A2 : 0x0000000f A3 : 0x00000001 A4 : 0x00000000 A5 : 0x3fcd454c A6 : 0x00000001 A7 : 0x3fcd454c A8 : 0x803860dd A9 : 0x3fcae450 A10 : 0x3fca5018 A11 : 0x3fca5018 A12 : 0x00060420 A13 : 0x00060423 A14 : 0x00000007 A15 : 0x0000abab SAR : 0x00000018 EXCCAUSE: 0x0000001c EXCVADDR: 0x00000017 LBEG : 0x40056f5c LEND : 0x40056f72 LCOUNT : 0xffffffff
Backtrace: 0x4038375a:0x3fcae470 0x4205bf39:0x3fcae490 0x42057098:0x3fcae4b0 0x42056ea6:0x3fcae530 0x42061466:0x3fcae560 0x4205b60d:0x3fcae5d0 0x4202458e:0x3fcae5f0 0x42023648:0x3fcae630 0x42023999:0x3fcae650 0x42133be7:0x3fcae670 0x42010ce9:0x3fcae690 0x40386796:0x3fcae6b0 0x4038375a: xQueueGiveMutexRecursive at C:/Espressif/frameworks/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:668 (discriminator 1)
0x4205bf39: esp_modem::Lock::unlock() at C:/Projects/ksc-2n/src/SERVICES/EspModem_Driver/src/esp_modem_primitives_freertos.cpp:26
0x42057098: esp_modem::Scoped
0x42056ea6: esp_modem::DTE::command(std::__cxx11::basic_string<char, std::char_traits
0x42061466: esp_modem::dce_commands::get_signal_quality(esp_modem::CommandableIf, int&, int&) at C:/Projects/ksc-2n/src/SERVICES/EspModem_Driver/src/esp_modem_command_library.cpp:69 (inlined by) esp_modem::dce_commands::get_signal_quality(esp_modem::CommandableIf, int&, int&) at C:/Projects/ksc-2n/src/SERVICES/EspModem_Driver/src/esp_modem_command_library.cpp:498
0x4205b60d: esp_modem::GenericModule::get_signal_quality(int&, int&) at C:/Projects/ksc-2n/src/SERVICES/EspModem_Driver/src/esp_modem_modules.cpp:48
0x4202458e: esp_modem::command_result esp_modem::DCE::get_signal_quality<int&, int&>(int&, int&) at C:/Projects/ksc-2n/src/SERVICES/EspModem_Driver/include/cxx_include/esp_modem_dce.hpp:117 (inlined by) ModemManager_UpdateModemInfo at C:/Projects/ksc-2n/src/SERVICES/EspModem_Manager/ModemManager_Wrapper.cpp:1988
0x42023648: ModemManager_ReadModemInfo at C:/Projects/ksc-2n/src/SERVICES/EspModem_Manager/ModemManager.c:785
0x42023999: ModemManager_MainFunction at C:/Projects/ksc-2n/src/SERVICES/EspModem_Manager/ModemManager.c:174
0x42133be7: osw::Event::run() const at C:/Projects/ksc-2n/src/OS/os_wrapper/src/Event.cpp:27
0x42010ce9: osw::Task<2u>::run(void*) at C:/Projects/ksc-2n/src/OS/os_wrapper/include/Task.hpp:213
0x40386796: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:151
ELF file SHA256: 5cb461b0acd0906f
I (25666) esp_core_dump_flash: Save core dump to flash... E (25672) esp_core_dump_flash: Not enough space to save core dump! E (25679) esp_core_dump_elf: Failed to prepare core dump storage (257)! E (25686) esp_core_dump_common: Core dump write binary failed with error=257 I (25694) esp_core_dump_flash: Core dump has been saved to flash. Rebooting... ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x10 (RTCWDT_RTC_RST),boot:0x2f (SPI_FAST_FLASH_BOOT)
david-cermak
commented
1 year ago Thanks for sharing the test results! This I think look more like a memory corruption, then a race condition. Load-Prohibited error when unlocking the recently added mutex here:
seems like the memory location of the the on_read_guard variable was 0x17 at the time of execution.
Looking at the position of that variable, inside the terminal and DTE respectively, it looks like it's located near
unique_buffer buffer; /*!< DTE buffer */Does your application take a pointer of some of the replies to process them? Is it possible that this you write to that location, when parsing? Are you using CMUX mode?
david-cermak
commented
1 year ago @RilabsAutomotive Please provide a minimal sample application that would exhibit the problem, as so far it looks like a memory corruption in your project.
MartinPatarinski
commented
1 year ago Ok, thank you for the answer. Creating a sample application would be a significant effort and for the moment this is a minor issue.
Alvin1Zhang
commented
1 year ago @RilabsAutomotive Thanks for reporting, would you please help share if any updates for the issue? Thanks.
Answers checklist.
IDF version.
v5.0-rc1
Operating System used.
Windows
How did you build your project?
Command line with idf.py
If you are using Windows, please specify command line type.
PowerShell
Development Kit.
ESP32-S3-WROOM-1-N16R
Power Supply used.
Battery
What is the expected behavior?
The Appl source code is requesting info (signal quality) from the modem(SIM7070) via AT command, that has an extended timeout of 15 sec. After that it issues another AT command to get the battery status. When no response to the first command is received by the SIM7070 within the defined timeout, the ESP Modem driver shall abort the execution of the command and any upcoming response.
What is the actual behavior?
Sporadically, the ESP modem driver crashes whenever a response is received by the SIM7070 while the ESP expects a response to the next AT command
} (12:34:13.259) command_lib: Command: {AT+CSQ I (12:34:14.990) EcuManager: Temperature value 52.50 ℃ I (12:34:25.010) EcuManager: Temperature value 52.94 ℃ E (12:34:28.259) ESPmodem_Cmux: Read SIMCOM signal strength failed // timeout 15 sec } (12:34:28.579) command_lib: Command: {AT+CBC // new AT command issued by the SIM7070 } (12:34:28.601) command_lib: Token: { I (12:34:28.602) command_lib: Token: {+CSQ: 19,99} // response at the first AT command after the timeout has expired } (12:34:28.602) command_lib: Token: { I (12:34:28.605) command_lib: Token: {OK} } (12:34:28.610) command_lib: Token: { E (12:34:28.610) ESPmodem_Cmux: Read SIMCOM battery status failed I (12:34:28.614) command_lib: Token: {+CBC: 0,97,4272} Guru Meditation Error: Core 0 panic'ed (StoreProhibited). Exception was unhandled. ...
Steps to reproduce.
Debug Logs.
More Information.
No response