PppoS: Uart Resync Problems (IDFGH-2354)

[MrCurio]

Environment

• Development Kit: ESP32-DevKitC
• Kit version (DevKitC): [v4]
• Module or chip used: [ESP32-WROOM-32D]
• IDF version (run git describe --tags to find it): v4.1-dev-369-g4dac7c7df-dirty
• Build System: [Make]
• Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp32-2019r1) 8.2.0
• Operating System: [Linux]
• Power Supply: [external 5V -> 4A max Current]

Problem Description

Hi! I have been testing the PppoS example for a while and it seems i found a bug or something.
I will describe my project and then i will explain the particular problem.

Project:
I am connecting to internet through the module Sim800L and then i make different operations such as http post and more. Since the module consumes a lot of energy, i implemented a MOSFET to turn on and off when desired for connecting to internet.

Problem:
When i start running my program (pppoS example extended for deinit before turning off module and init again when is back on) everything works good until I try to resync when i turn on the module. It gets stuck when i try to access the PPP mode again. Looks like the deinit function is not doing the right job.
It seems that there's a blocking function called: "pppapi_ppos_create" in the file esp_modem.c that blocks my program causing a immediate reset on the ESP32.

Problems Checked:

1. I know that the module Sim800L needs a high amount of current but those problems are solved thanks to my external battery as described above.
2. When i turn on the module, it takes about 10 seconds for getting the signal but my program waits enough for the module to be in an operative mode.
3. I tried to solve the problem without deinit (both dte and dce) but when reconnection, resets again, even though after a few resets it gets back to normal. But i want to avoid resets at all except for emergency problems.

Expected Behavior

When i run the script described, the module turns on/off, without reset, allowing me to connect to internet whenever i want by turning on the mosfet.

Actual Behavior

Everything works perfect until the modules turn on, after turning off and deinit, that's when the esp32 resets and all the program starts from scratch.

Question

Is there any way to resync the communication between the esp32 and the module without reseting?

Steps to repropduce

1. Copy and paste de PppoS Example from the github
2. Configure a GPIO for turning ON/OFF the mosfet (IRL3705)
3. Turn off the module using the GPIO (Assuming you deinit in the first step!)
4. Wait a few seconds and turn it back on
5. Wait about 15-20 seconds until the module get connection (blinks every 3 seconds or so)
6. Once the module gets connection, init again dte and dce.
7. Get into PPP Mode
8. Crashes! Or sometimes it doesnt crash and it stays in the function "pppapi_ppos_create" until i stop the program.

Code to reproduce this issue

PppoS example, copied exactly the same and added the following lines:

    gpio_config_t io_conf;
    io_conf.intr_type = GPIO_PIN_INTR_DISABLE;
    io_conf.mode = GPIO_MODE_OUTPUT;
    io_conf.pull_down_en = 0;
    io_conf.pull_up_en = 0;
    io_conf.pin_bit_mask = (1ULL<<GPIO_NUM_14);
    gpio_config(&io_conf);
    gpio_set_level(GPIO_NUM_14, 0); // Turn OFF module

    vTaskDelay(5000 / portTICK_PERIOD_MS); //Wait for 5 seconds to turn it back ON
    gpio_set_level(GPIO_NUM_14, 1); // Turn ON the module
    vTaskDelay(15000 / portTICK_PERIOD_MS); // Wait 15 seconds for module to reconnect
    dte = esp_modem_dte_init(&config);
    /* Register event handler */
    ESP_ERROR_CHECK(esp_modem_add_event_handler(dte, modem_event_handler, NULL));
    /* create dce object */
    dce = sim800_init(dte);

    ESP_ERROR_CHECK(dce->set_flow_ctrl(dce, MODEM_FLOW_CONTROL_NONE));
    ESP_ERROR_CHECK(dce->store_profile(dce));
    /* Print Module ID, Operator, IMEI, IMSI */
    ESP_LOGI(TAG, "Module: %s", dce->name);
    ESP_LOGI(TAG, "Operator: %s", dce->oper);
    ESP_LOGI(TAG, "IMEI: %s", dce->imei);
    ESP_LOGI(TAG, "IMSI: %s", dce->imsi);

    /* Get signal quality */
    rssi = 0;
    ber = 0;
    ESP_ERROR_CHECK(dce->get_signal_quality(dce, &rssi, &ber));
    ESP_LOGI(TAG, "rssi: %d, ber: %d", rssi, ber);
    /* Get battery voltage */
    voltage = 0;
    bcs = 0;
    bcl = 0;
    ESP_ERROR_CHECK(dce->get_battery_status(dce, &bcs, &bcl, &voltage));
    ESP_LOGI(TAG, "Battery voltage: %d mV", voltage);

    /* Setup PPP environment */
    ESP_LOGI(TAG, "ENTRANDO EN EL MODO PPP");
    esp_modem_setup_ppp(dte); //Here is where stacks!
    /* Wait for IP address */
    xEventGroupWaitBits(event_group, CONNECT_BIT, pdTRUE, pdTRUE, portMAX_DELAY);
    ESP_LOGI(TAG, "PROGRAMA ACABADO");

}

Debug Logs

I (36366) esp-modem: ENTRANDO EN EL MODO PPP //Coments in the esp_modem file for debugging and the function below is where it stacks or it looks like is there!
I (36466) esp-modem: pppapi_ppos_create_stacks!!
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC      : 0x4010027e  PS      : 0x00060b30  A0      : 0x800d4621  A1      : 0x3ffb9d40  
0x4010027e: pppos_input_tcpip at /home/juan-platero/esp/esp-idf/components/lwip/lwip/src/netif/ppp/pppos.c:440

A2      : 0x00000000  A3      : 0x3ffba384  A4      : 0x0000002b  A5      : 0x3ffbd1a4  
A6      : 0x3ffb4ddc  A7      : 0x0000002b  A8      : 0x8010027b  A9      : 0x3ffb9d20  
A10     : 0x00000000  A11     : 0x3ffba384  A12     : 0x401004e4  A13     : 0x0000002b  
0x401004e4: pppos_input_sys at /home/juan-platero/esp/esp-idf/components/lwip/lwip/src/netif/ppp/pppos.c:448

A14     : 0x0000002b  A15     : 0x0000002b  SAR     : 0x00000010  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0000002c  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x00000000  

ELF file SHA256: d6c2077cda2ac5abc4fb7158147ef57ba820cd4251b6f6c07e2df8decbac3d35

Backtrace: 0x4010027b:0x3ffb9d40 0x400d461e:0x3ffb9d60 0x400d4777:0x3ffb9d90 0x40088985:0x3ffb9dc0
0x4010027b: pppos_input_tcpip at /home/juan-platero/esp/esp-idf/components/lwip/lwip/src/netif/ppp/pppos.c:440

0x400d461e: esp_handle_uart_data at /home/juan-platero/esp/esp-idf/examples/protocols/pppos_client/components/modem/src/esp_modem.c:140

0x400d4777: uart_event_task_entry at /home/juan-platero/esp/esp-idf/examples/protocols/pppos_client/components/modem/src/esp_modem.c:157

0x40088985: vPortTaskWrapper at /home/juan-platero/esp/esp-idf/components/freertos/port.c:143


Rebooting...

If its useful, after the first reboot, i get a "NO CARRIER" error and it resets multiple times until it gets sync again

Other items if possible

There are no other files than the ones in the example.

Thank you!!

[cima]

I ran exactly into this issue during "implementation" of driver for modem M590E. I have the very same stack trace and the main reason why it crashes is in function pppos_input_tcpip where structure ppp_pcb is being accesed. Structure is passed from one level up function esp_handle_uart_data

pppos_input_tcpip(esp_dte->ppp, esp_dte->buffer, length);

The flow of the example communicates with modem over UART prior the esp_dte->ppp is initialized and thus you end up in a null pointer derefenrence pppos_input_tcpip which closes the proof.
I am hacking esp-idf and esp-iot-solution like crazy so I hopefully win and provide pull request (and fork). I have split method esp_modem_setup_ppp from esp_modem.c in a way I call the memory allocation part before any UART transmission takes place and the rest later. It helped me to move one. Now I am fighting AT commands, but will provide Work-in-progress fork soon so you can hack the example according to your needs.

[fetiennex]

I ran exactly into this issue during "implementation" of driver for modem M590E. I have the very same stack trace and the main reason why it crashes is in function pppos_input_tcpip where structure ppp_pcb is being accesed. Structure is passed from one level up function esp_handle_uart_data

pppos_input_tcpip(esp_dte->ppp, esp_dte->buffer, length);

The flow of the example communicates with modem over UART prior the esp_dte->ppp is initialized and thus you end up in a null pointer derefenrence pppos_input_tcpip which closes the proof.
I am hacking esp-idf and esp-iot-solution like crazy so I hopefully win and provide pull request (and fork). I have split method esp_modem_setup_ppp from esp_modem.c in a way I call the memory allocation part before any UART transmission takes place and the rest later. It helped me to move one. Now I am fighting AT commands, but will provide Work-in-progress fork soon so you can hack the example according to your needs.

Hi, do you have by any chance an example of how you split esp_modem_setup_ppp ? I have had the same problem with a sim800l, the program boots the first time, crashes on esp_modem_dte_init call for the reason you described, then reboots and works without problem this time, and i don't know why.

[cima]

I haven't progress to prepare fix for esp-iot-solution. My work remained at the phase of workaround ModemManager.cpp:L39 where I mange the modem lifecycle on my own. (It is also related to significantly different flow and API of M590e modem) I simply make sure structure is fully initialized and then I call connection routine.

I am sorry I can't help you bit more. My life made me to put this IoT project on hold for a while.

[fetiennex]

I haven't progress to prepare fix for esp-iot-solution. My work remained at the phase of workaround ModemManager.cpp:L39 where I mange the modem lifecycle on my own. (It is also related to significantly different flow and API of M590e modem) I simply make sure structure is fully initialized and then I call connection routine.

I am sorry I can't help you bit more. My life made me to put this IoT project on hold for a while.

Thanks a lot for your fast reply. So i studied your code a bit, and it seems to me we have quite similar codes for the ModemManager. I noticed there is a .init() method for initializing the dte which calls esp_modem_dte_init(&config), wouldn't that be the call that tries to do " pppos_input_tcpip(esp_dte->ppp, esp_dte->buffer, length) " ? Unless you modified it ? Because esp_modem_setup_ppp is still in the connect routine, which needs an initialized dte. I don't understand how to solve the paradox of both needing a ppp to initialize the dte because of the pppos_input_tcpip call and needing the dte to setup the ppp.

Don't worry about it, this help is precious already.

[fetiennex]

I think I understood why the program resets. The reason why esp_handle_uart_data is called before esp_modem_setup_ppp is because before setting up ppp, we apply the uart event routing (xTaskCreate(uart_event_task_entry)) in esp_modem_dte_init, but at this point the uart shouldn't receive a UART_DATA type of event as it needs the ppp to be set to call pppos_input_tcpip. However, it apparently does, according to this comment: #3506 (comment) . So the solution i found is adding a simple boolean in esp_modem.c that i turn on once esp_modem_setup_ppp has been called that allows the uart_event_task_entry to call esp_handle_uart_data.

[Alvin1Zhang]

Thanks for reporting and sorry for slow turnaround, we have a fix under internal reviewing now, and the issue will close automatically once the fix is available on GitHub, thanks.