PPP error with SIM800L, after ESP restart in the middle of PPP. (IDFGH-2170)

Arthedian commented 4 years ago

Development Kit: ESP32-DevKitC
Module or chip used: ESP32-WROOM-32
IDF version (run git describe --tags to find it): v4.0-beta2-70-g0a03a55c1
Build System: CMake
Compiler version (run xtensa-esp32-elf-gcc --version to find it): (crosstool-NG esp32-2019r1) 8.2.0
Operating System: Fedora 31
Power Supply: USB.

Problem Description

I am using official example for PPP protocol with SIM800L and it is running without problem, but if I manually restart the ESP (not the modem), that it is repeatly starts to restart itself //Detailed problem description goes here.

Expected Behavior

Run without problem and connect to the modem

Actual Behavior

I (0) cpu_start: Starting scheduler on APP CPU.
I (451) uart: queue free spaces: 30
E (961) esp-modem: esp_modem_dte_send_cmd(215): process command timeout
E (961) dce_service: esp_modem_dce_sync(48): send command failed
E (961) sim800: sim800_init(460): sync failed
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC      : 0x400d6438  PS      : 0x00060130  A0      : 0x800d28ed  A1      : 0x3ffb60b0  
0x400d6438: app_main at /home/arthedian/prace/BeiT/test/pppos_client/build/../main/pppos_client_main.c:199

A2      : 0x00000000  A3      : 0x00000001  A4      : 0x3ffb956c  A5      : 0x00000001  
A6      : 0x00060021  A7      : 0x00060023  A8      : 0x800d6436  A9      : 0x3ffb6080  
A10     : 0x00000000  A11     : 0x3ffbb048  A12     : 0x400d7680  A13     : 0x3ffb60d8  
0x400d7680: sim800_deinit at /home/arthedian/prace/BeiT/test/pppos_client/build/../components/modem/src/sim800.c:428

A14     : 0x00000000  A15     : 0x0001c200  SAR     : 0x00000004  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0000007c  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffc  

ELF file SHA256: 5a0dd812a8fb9cc18399296c0ae66d22ef70241d4bb3dfdcb53cc3b9d70a2e37

Backtrace: 0x400d6435:0x3ffb60b0 0x400d28ea:0x3ffb6190 0x40087da9:0x3ffb61b0
0x400d6435: app_main at /home/arthedian/prace/BeiT/test/pppos_client/build/../main/pppos_client_main.c:193

0x400d28ea: main_task at /home/arthedian/esp/esp-idf/components/esp32/cpu_start.c:553

0x40087da9: vPortTaskWrapper at /home/arthedian/esp/esp-idf/components/freertos/port.c:143

Steps to reproduce

Run official example for PPP protocol with SIM800L
Wait until it will say "pppos_example: Modem PPP Started"
Manually restart
Wait until the error

suda-morris commented 4 years ago

yes, the example doesn't handle much edge conditions, it assumes that when calling sim800_init(dte); we can get a valid dce object pointer. But in your case, sim800l doesn't get reset so esp32 can sync with it by AT command, therefore, we won't get a valid dce object pointer, so crash happend, because dce pointer is NULL. You can use a GPIO to reset sim800l if you have to.

Arthedian commented 4 years ago

Hello, Thanks for the info, I fixed it in my program. But still I am testing your example code. I a trying to repeteadly connect to PPP and dissconnect and than again (I added simple for cycle, I attached the code). When I call esp_modem_setup_ppp for the second time (after disconnecting it first), than it freezes and wont do anything. WHy?

 (442) uart: queue free spaces: 30
I (1602) pppos_example: Module: SIMCOM_SIM800L
I (1602) pppos_example: Operator: "OSKAR"
I (1602) pppos_example: IMEI: 867856031777128
I (1602) pppos_example: IMSI: 230030158030911
I (1802) pppos_example: rssi: 30, ber: 0
I (2002) pppos_example: Battery voltage: 4087 mV
start of for
I (2202) pppos_example: Modem PPP Started
wait until connect
I (2952) pppos_example: Modem Connect to PPP Server
I (2952) pppos_example: ~~~~~~~~~~~~~~
I (2952) pppos_example: IP          : 10.169.119.31
I (2952) pppos_example: Netmask     : 255.255.255.255
I (2962) pppos_example: Gateway     : 192.168.254.254
I (2962) pppos_example: Name Server1: 217.77.165.211
I (2972) pppos_example: Name Server2: 217.77.165.81
I (2972) pppos_example: ~~~~~~~~~~~~~~
connected
I (2982) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (2992) pppos_example: MQTT other event id: 7
I (3752) MQTT_CLIENT: Sending MQTT CONNECT message, type: 1, id: 0000
I (4242) pppos_example: MQTT_EVENT_CONNECTED
I (4242) pppos_example: sent subscribe successful, msg_id=38991
I (4542) pppos_example: MQTT_EVENT_SUBSCRIBED, msg_id=38991
I (4542) pppos_example: sent publish successful, msg_id=0
I (4882) pppos_example: MQTT_EVENT_DATA
TOPIC=/topic/esp-pppos
DATA=esp32-pppos
I (5202) pppos_example: Modem PPP Stopped
wait until stopp
stopped
start of for

pppos_client_main.zip

Arthedian commented 4 years ago

It is stucked on this line:

esp_dte->ppp = pppapi_pppos_create(&(esp_dte->pppif), pppos_low_level_output, on_ppp_status_changed, dte);

Arthedian commented 4 years ago

@suda-morris any news?

MrCurio commented 4 years ago

Same Problem over here! No solution so far! I guess we will have to handle on our own the errors, dont know how yet

d3vil-st commented 4 years ago

In my case I resolved it with that code:

          /* Exit PPP mode */
          ESP_ERROR_CHECK(esp_modem_exit_ppp(dte));
          /* De-initialization of all modem resources*/
          ESP_ERROR_CHECK(dce->deinit(dce));
          ESP_ERROR_CHECK(dte->deinit(dte));
          dte = NULL;
          dce = NULL;

I'm not sure that can cause a memory leak, but at least it works. Also you have to modify component checkout my pull request: #4653

Arthedian commented 4 years ago

Are you successful to init it again after deinit?

d3vil-st commented 4 years ago

Are you successful to init it again after deinit?

Yes, I'm deiniting all resources cause I rebooting modem.

Arthedian commented 4 years ago

@d3vil-st I cloned your ESP idf branch, but the PPP example throws me errors.

Firstly it threw me an error on line 266 of main on power down function. It didnt made me sense to have it there, so i comment it out.

I (3235) pppos_example: GOT ip event!!!
E (4235) esp-modem: esp_modem_dte_send_cmd(221): process command timeout
E (4235) sim800: sim800_power_down(331): send command failed
ESP_ERROR_CHECK failed: esp_err_t 0xffffffff (ESP_FAIL) at 0x40085fc4
0x40085fc4: _esp_error_check_failed at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:739

file: "../main/pppos_client_main.c" line 266
func: app_main
expression: dce->power_down(dce)

ELF file SHA256: 32b9211ace877dc2b597063454e2321131224a1f7378a7f2cecdfbd98450318d

Backtrace: 0x40085a15:0x3ffb5b20 0x40085fc7:0x3ffb5b40 0x400d658c:0x3ffb5b60 0x400d2952:0x3ffb5c50 0x400882ed:0x3ffb5c70
0x40085a15: invoke_abort at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:157

0x40085fc7: _esp_error_check_failed at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:740

0x400d658c: app_main at /home/arthedian/prace/BeiT/test/pppos_client/build/../main/pppos_client_main.c:266 (discriminator 1)

0x400d2952: main_task at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/cpu_start.c:564

0x400882ed: vPortTaskWrapper at /home/arthedian/esp/esp-idf_working_gsm.git/components/freertos/port.c:143

After that another error appeared:

I (25183) pppos_example: MQTT_EVENT_CONNECTED
D (25193) MQTT_CLIENT: mqtt_enqueue id: 16926, type=8 successful
D (25203) OUTBOX: ENQUEUE msgid=16926, msg_type=8, len=23, size=23
D (25203) MQTT_CLIENT: Sent subscribe topic=/topic/esp-pppos, id: 16926, type=8 successful
I (25213) pppos_example: sent subscribe successful, msg_id=16926
D (25563) MQTT_CLIENT: mqtt_message_receive: first byte: 0x90
D (25563) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x3
D (25563) MQTT_CLIENT: mqtt_message_receive: total message length: 5 (already read: 2)
D (25573) MQTT_CLIENT: mqtt_message_receive: read_len=3
D (25573) MQTT_CLIENT: mqtt_message_receive: transport_read():5 5
D (25583) MQTT_CLIENT: msg_type=9, msg_id=16926
D (25583) MQTT_CLIENT: pending_id=16926, pending_msg_count = 1
D (25593) OUTBOX: DELETED msgid=16926, msg_type=8, remain size=0
D (25593) MQTT_CLIENT: Subscribe successful
I (25603) pppos_example: MQTT_EVENT_SUBSCRIBED, msg_id=16926
I (25613) pppos_example: sent publish successful, msg_id=0
D (26063) MQTT_CLIENT: mqtt_message_receive: first byte: 0x30
D (26063) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x1d
D (26063) MQTT_CLIENT: mqtt_message_receive: total message length: 31 (already read: 2)
D (26073) MQTT_CLIENT: mqtt_message_receive: read_len=29
D (26073) MQTT_CLIENT: mqtt_message_receive: transport_read():31 31
D (26083) MQTT_CLIENT: msg_type=3, msg_id=0
D (26083) MQTT_CLIENT: deliver_publish, message_length_read=31, message_length=31
D (26093) MQTT_CLIENT: deliver_publish: msg_topic_len=16
D (26103) MQTT_CLIENT: Get data len= 11, topic len=16, total_data: 11 offset: 0
I (26103) pppos_example: MQTT_EVENT_DATA
TOPIC=/topic/esp-pppos
DATA=esp32-pppos
D (26423) event: deleted loop 0x3ffbcf7c
E (26773) esp-modem: esp_dte_handle_line(90): handle line failed
D (26783) event: running post ESP_MODEM_EVENT:4 with handler 0x400d6330 on loop 0x3ffbb658
0x400d6330: modem_event_handler at /home/arthedian/prace/BeiT/test/pppos_client/build/../main/pppos_client_main.c:114

W (26783) pppos_example: Unknow line received: ~!E
E (29423) esp-modem: esp_modem_dte_send_cmd(221): process command timeout
E (29423) sim800: sim800_set_working_mode(297): send command failed
E (29423) esp-modem: esp_modem_dte_change_mode(311): set new working mode:0 failed
E (29433) esp-modem: esp_modem_stop_ppp(482): enter command mode failed
ESP_ERROR_CHECK failed: esp_err_t 0xffffffff (ESP_FAIL) at 0x40086034
0x40086034: _esp_error_check_failed at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:739

file: "../main/pppos_client_main.c" line 300
func: app_main
expression: esp_modem_stop_ppp(dte)

ELF file SHA256: 1af55e0a4e51c0cd095b7901572eda8ff3fd71b98e3a906c5ac8764062fe83d0

Backtrace: 0x40085a85:0x3ffb5b90 0x40086037:0x3ffb5bb0 0x400d67bc:0x3ffb5bd0 0x400d2a66:0x3ffb5ce0 0x4008835d:0x3ffb5d00
0x40085a85: invoke_abort at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:157

0x40086037: _esp_error_check_failed at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:740

0x400d67bc: app_main at /home/arthedian/prace/BeiT/test/pppos_client/build/../main/pppos_client_main.c:300 (discriminator 1)

0x400d2a66: main_task at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/cpu_start.c:564

Can you help me to fix it?

d3vil-st commented 4 years ago

@Arthedian Try to stop mqtt client with esp_mqtt_client_stop(esp_mqtt_client_handle); before closing PPP session.

Arthedian commented 4 years ago

I commented out the mqtt client stuff and add small http request. still the same problem:

W (27239) esp-modem: Ring Buffer Full
E (27319) esp-modem: esp_dte_handle_line(90): handle line failed
D (27319) event: running post ESP_MODEM_EVENT:4 with handler 0x400d5774 on loop 0x3ffbb298
0x400d5774: modem_event_handler at /home/arthedian/prace/BeiT/test/pppos_client/build/../main/pppos_client_main.c:116

W (27319) pppos_example: Unknow line received: ~!E
E (29879) esp-modem: esp_modem_dte_send_cmd(221): process command timeout
E (29879) sim800: sim800_set_working_mode(297): send command failed
E (29879) esp-modem: esp_modem_dte_change_mode(311): set new working mode:0 failed
E (29889) esp-modem: esp_modem_stop_ppp(482): enter command mode failed
ESP_ERROR_CHECK failed: esp_err_t 0xffffffff (ESP_FAIL) at 0x40085fe0
0x40085fe0: _esp_error_check_failed at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:739

file: "../main/pppos_client_main.c" line 394
func: app_main
expression: esp_modem_stop_ppp(dte)

ELF file SHA256: 7022f54bcb247c32e02bfdc2c79b6caa9e3ab8c6bf6df060c145de75643518a7

Backtrace: 0x40085a31:0x3ffb5860 0x40085fe3:0x3ffb5880 0x400d5dbb:0x3ffb58a0 0x400d262e:0x3ffb5920 0x40088309:0x3ffb5940
0x40085a31: invoke_abort at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:157

0x40085fe3: _esp_error_check_failed at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/panic.c:740

0x400d5dbb: app_main at /home/arthedian/prace/BeiT/test/pppos_client/build/../main/pppos_client_main.c:394 (discriminator 1)

0x400d262e: main_task at /home/arthedian/esp/esp-idf_working_gsm.git/components/esp32/cpu_start.c:564

0x40088309: vPortTaskWrapper at /home/arthedian/esp/esp-idf_working_gsm.git/components/freertos/port.c:143

HTTP get function:

#define WEB_SERVER "www.example.com"
#define WEB_PORT "80"
#define WEB_PATH "/"

static const char *REQUEST = "GET " WEB_PATH " HTTP/1.0\r\n"
                             "Host: "WEB_SERVER":"WEB_PORT"\r\n"
                             "User-Agent: esp-idf/1.0 esp32\r\n"
                             "\r\n";

void http_get() {

    const struct addrinfo hints = {
            .ai_family = AF_INET,
            .ai_socktype = SOCK_STREAM,
    };
    struct addrinfo *res;
    struct in_addr *addr;
    int s, r;
    char recv_buf[64];

    for (int j = 0; j < 2; ++j) {

        int err = getaddrinfo(WEB_SERVER, WEB_PORT, &hints, &res);

        if (err != 0 || res == NULL) {
            ESP_LOGE(TAG, "DNS lookup failed err=%d res=%p", err, res);
            vTaskDelay(1000 / portTICK_PERIOD_MS);
            continue;
        }

        /* Code to print the resolved IP.
           Note: inet_ntoa is non-reentrant, look at ipaddr_ntoa_r for "real" code */
        addr = &((struct sockaddr_in *) res->ai_addr)->sin_addr;
        ESP_LOGI(TAG, "DNS lookup succeeded. IP=%s", inet_ntoa(*addr));

        s = socket(res->ai_family, res->ai_socktype, 0);
        if (s < 0) {
            ESP_LOGE(TAG, "... Failed to allocate socket.");
            freeaddrinfo(res);
            vTaskDelay(1000 / portTICK_PERIOD_MS);
            continue;
        }
        ESP_LOGI(TAG, "... allocated socket");

        if (connect(s, res->ai_addr, res->ai_addrlen) != 0) {
            ESP_LOGE(TAG, "... socket connect failed errno=%d", errno);
            close(s);
            freeaddrinfo(res);
            vTaskDelay(4000 / portTICK_PERIOD_MS);
            continue;
        }

        ESP_LOGI(TAG, "... connected");
        freeaddrinfo(res);

        if (write(s, REQUEST, strlen(REQUEST)) < 0) {
            ESP_LOGE(TAG, "... socket send failed");
            close(s);
            vTaskDelay(4000 / portTICK_PERIOD_MS);
            continue;
        }
        ESP_LOGI(TAG, "... socket send success");

        struct timeval receiving_timeout;
        receiving_timeout.tv_sec = 5;
        receiving_timeout.tv_usec = 0;
        if (setsockopt(s, SOL_SOCKET, SO_RCVTIMEO, &receiving_timeout,
                       sizeof(receiving_timeout)) < 0) {
            ESP_LOGE(TAG, "... failed to set socket receiving timeout");
            close(s);
            vTaskDelay(4000 / portTICK_PERIOD_MS);
            continue;
        }
        ESP_LOGI(TAG, "... set socket receiving timeout success");

        /* Read HTTP response */
        do {
            bzero(recv_buf, sizeof(recv_buf));
            r = read(s, recv_buf, sizeof(recv_buf) - 1);
            for (int i = 0; i < r; i++) {
                putchar(recv_buf[i]);
            }
        } while (r > 0);

        ESP_LOGI(TAG, "... done reading from socket. Last read return=%d errno=%d.", r, errno);
        close(s);
    }
}

Arthedian commented 4 years ago

@d3vil-st Is the ppp example on your branch working for you?

martinpala commented 4 years ago

Using IDF 4.1

This worked for me:

ESP_ERROR_CHECK(dce->deinit(dce)); ESP_ERROR_CHECK(dte->deinit(dte)); ESP_ERROR_CHECK(esp_event_loop_delete_default());

After calling esp_event_loop_delete_default() - I am able to re-init again

espressif / esp-idf