espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.91k stars 7.33k forks source link

SIM800L PPPoS Client stops working after some hours with pppos_input_tcpip failed with -1 (IDFGH-4236) #6094

Closed berkutta closed 3 years ago

berkutta commented 4 years ago

Using ESP-IDF 357a2776032299b8bc4044900a8f1d6950d7ce89 with modified example https://github.com/espressif/esp-idf/tree/master/examples/protocols/pppos_client on a LILYGO TTGO T-Call Publishing MQTT Messages every 10 Second.

Publishing to topic /topic/esp-860389056310861/status
test0
Received data from Modem: ~!E, 37 Bytes
7E 21 45 0 0 28 40 9A 40 0 2B 6 97 56 89 87 53 D9 A C1 8F BE 7 5B DD D4 F3 E3 5B 10 0 4 99 7C 50 10 FF
Received data from Modem: �jP, 8 Bytes
FF 6A 50 0 0 E2 4B 7E
Publishing to topic /topic/esp-860389056310861/status
test0
Received data from Modem: ~!E, 37 Bytes
7E 21 45 0 0 28 40 9B 40 0 2B 6 97 55 89 87 53 D9 A C1 8F BE 7 5B DD D4 F3 E3 5B 10 0 4 9A 21 50 10 FF
Received data from Modem: �i�, 8 Bytes
FF 69 AB 0 0 8A A5 7E
^[[0;31mE (17968901) esp-netif_lwip-ppp: pppos_input_tcpip failed with -1^[[0m
Publishing to topic /topic/esp-860389056310861/status
test0
Publishing to topic /topic/esp-860389056310861/status
test0
Publishing to topic /topic/esp-860389056310861/status
test0
MrCurio commented 3 years ago

Hello @berkutta , Could you please share your code to check if i find something strange?

Have you checked other issues relates to pppos, there might be something related.

I'm not an expert but i worked with the Sim800L for hours and no problems.

berkutta commented 3 years ago

Hi @MrCurio

This is my code, it's basically the PPPoS Example with some modifications to send messages every 10 seconds and also turn on the modem via GPIO. It works fine for ~12 hours and then fails with pppos_input_tcpip returning -1 at some point.

/* PPPoS Client Example

   This example code is in the Public Domain (or CC0 licensed, at your option.)

   Unless required by applicable law or agreed to in writing, this
   software is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR
   CONDITIONS OF ANY KIND, either express or implied.
*/
#include <string.h>
#include "freertos/FreeRTOS.h"
#include "freertos/event_groups.h"
#include "esp_netif.h"
#include "esp_netif_ppp.h"
#include "mqtt_client.h"
#include "esp_modem.h"
#include "esp_modem_netif.h"
#include "esp_log.h"
#include "sim800.h"
#include "bg96.h"
#include "sim7600.h"

#include "cJSON.h"
#include "driver/gpio.h"

#define BROKER_URL "mqtt://mqtt.eclipse.org"

static const char *TAG = "pppos_example";
static EventGroupHandle_t event_group = NULL;
static const int CONNECT_BIT = BIT0;
static const int STOP_BIT = BIT1;
static const int GOT_DATA_BIT = BIT2;

static void modem_event_handler(void *event_handler_arg, esp_event_base_t event_base, int32_t event_id, void *event_data)
{
    switch (event_id) {
    case ESP_MODEM_EVENT_PPP_START:
        ESP_LOGI(TAG, "Modem PPP Started");
        break;
    case ESP_MODEM_EVENT_PPP_STOP:
        ESP_LOGI(TAG, "Modem PPP Stopped");
        xEventGroupSetBits(event_group, STOP_BIT);
        break;
    case ESP_MODEM_EVENT_UNKNOWN:
        ESP_LOGW(TAG, "Unknow line received: %s", (char *)event_data);
        break;
    default:
        break;
    }
}

static esp_err_t mqtt_event_handler(esp_mqtt_event_handle_t event)
{
    esp_mqtt_client_handle_t client = event->client;
    int msg_id;
    switch (event->event_id) {
    case MQTT_EVENT_CONNECTED:
        ESP_LOGI(TAG, "MQTT_EVENT_CONNECTED");
        //msg_id = esp_mqtt_client_subscribe(client, "/topic/esp-pppos", 0);
        //ESP_LOGI(TAG, "sent subscribe successful, msg_id=%d", msg_id);
        break;
    case MQTT_EVENT_DISCONNECTED:
        ESP_LOGI(TAG, "MQTT_EVENT_DISCONNECTED");
        break;
    case MQTT_EVENT_SUBSCRIBED:
        ESP_LOGI(TAG, "MQTT_EVENT_SUBSCRIBED, msg_id=%d", event->msg_id);
        msg_id = esp_mqtt_client_publish(client, "/topic/esp-pppos", "esp32-pppos", 0, 0, 0);
        ESP_LOGI(TAG, "sent publish successful, msg_id=%d", msg_id);
        break;
    case MQTT_EVENT_UNSUBSCRIBED:
        ESP_LOGI(TAG, "MQTT_EVENT_UNSUBSCRIBED, msg_id=%d", event->msg_id);
        break;
    case MQTT_EVENT_PUBLISHED:
        ESP_LOGI(TAG, "MQTT_EVENT_PUBLISHED, msg_id=%d", event->msg_id);
        break;
    case MQTT_EVENT_DATA:
        ESP_LOGI(TAG, "MQTT_EVENT_DATA");
        printf("TOPIC=%.*s\r\n", event->topic_len, event->topic);
        printf("DATA=%.*s\r\n", event->data_len, event->data);
        //xEventGroupSetBits(event_group, GOT_DATA_BIT);
        break;
    case MQTT_EVENT_ERROR:
        ESP_LOGI(TAG, "MQTT_EVENT_ERROR");
        break;
    default:
        ESP_LOGI(TAG, "MQTT other event id: %d", event->event_id);
        break;
    }
    return ESP_OK;
}

static void on_ppp_changed(void *arg, esp_event_base_t event_base,
                           int32_t event_id, void *event_data)
{
    ESP_LOGI(TAG, "PPP state changed event %d", event_id);
    if (event_id == NETIF_PPP_ERRORUSER) {
        /* User interrupted event from esp-netif */
        esp_netif_t *netif = event_data;
        ESP_LOGI(TAG, "User interrupted event from netif:%p", netif);
    }
}

static void on_ip_event(void *arg, esp_event_base_t event_base,
                        int32_t event_id, void *event_data)
{
    ESP_LOGD(TAG, "IP event! %d", event_id);
    if (event_id == IP_EVENT_PPP_GOT_IP) {
        esp_netif_dns_info_t dns_info;

        ip_event_got_ip_t *event = (ip_event_got_ip_t *)event_data;
        esp_netif_t *netif = event->esp_netif;

        ESP_LOGI(TAG, "Modem Connect to PPP Server");
        ESP_LOGI(TAG, "~~~~~~~~~~~~~~");
        ESP_LOGI(TAG, "IP          : " IPSTR, IP2STR(&event->ip_info.ip));
        ESP_LOGI(TAG, "Netmask     : " IPSTR, IP2STR(&event->ip_info.netmask));
        ESP_LOGI(TAG, "Gateway     : " IPSTR, IP2STR(&event->ip_info.gw));
        esp_netif_get_dns_info(netif, 0, &dns_info);
        ESP_LOGI(TAG, "Name Server1: " IPSTR, IP2STR(&dns_info.ip.u_addr.ip4));
        esp_netif_get_dns_info(netif, 1, &dns_info);
        ESP_LOGI(TAG, "Name Server2: " IPSTR, IP2STR(&dns_info.ip.u_addr.ip4));
        ESP_LOGI(TAG, "~~~~~~~~~~~~~~");
        xEventGroupSetBits(event_group, CONNECT_BIT);

        ESP_LOGI(TAG, "GOT ip event!!!");
    } else if (event_id == IP_EVENT_PPP_LOST_IP) {
        ESP_LOGI(TAG, "Modem Disconnect from PPP Server");
    } else if (event_id == IP_EVENT_GOT_IP6) {
        ESP_LOGI(TAG, "GOT IPv6 event!");

        ip_event_got_ip6_t *event = (ip_event_got_ip6_t *)event_data;
        ESP_LOGI(TAG, "Got IPv6 address " IPV6STR, IPV62STR(event->ip6_info.ip));
    }
}

TimerHandle_t xTimer;
esp_mqtt_client_handle_t mqtt_client;

void vTimerCallback( TimerHandle_t xTimer )
{
    static uint32_t loop = 0;

    cJSON *root = cJSON_CreateObject();
    cJSON *device = cJSON_CreateObject();

    cJSON_AddNumberToObject(device, "loop", loop);

    cJSON_AddItemToObject(root, "device", device);

    char publish_topic[60];
    sprintf(publish_topic, "/topic/esp-%d/status", 1234);
    esp_mqtt_client_publish(mqtt_client, publish_topic, cJSON_PrintUnformatted(root), 0, 0, 0);

    printf("Publishing to topic %s \n", publish_topic);

    cJSON_Delete(root);
    free(root);

    loop++;
}

#define MODEM_RST            5
#define MODEM_PWKEY          4
#define MODEM_POWER_ON       23

void app_main(void)
{
#if CONFIG_LWIP_PPP_PAP_SUPPORT
    esp_netif_auth_type_t auth_type = NETIF_PPP_AUTHTYPE_PAP;
#elif CONFIG_LWIP_PPP_CHAP_SUPPORT
    esp_netif_auth_type_t auth_type = NETIF_PPP_AUTHTYPE_CHAP;
#elif !defined(CONFIG_EXAMPLE_MODEM_PPP_AUTH_NONE)
#error "Unsupported AUTH Negotiation"
#endif
    ESP_ERROR_CHECK(esp_netif_init());
    ESP_ERROR_CHECK(esp_event_loop_create_default());
    ESP_ERROR_CHECK(esp_event_handler_register(IP_EVENT, ESP_EVENT_ANY_ID, &on_ip_event, NULL));
    ESP_ERROR_CHECK(esp_event_handler_register(NETIF_PPP_STATUS, ESP_EVENT_ANY_ID, &on_ppp_changed, NULL));

    event_group = xEventGroupCreate();

    gpio_config_t io_conf;
    io_conf.intr_type = GPIO_INTR_DISABLE;
    io_conf.mode = GPIO_MODE_OUTPUT;
    io_conf.pin_bit_mask = (1<<MODEM_RST) | (1<<MODEM_PWKEY) | (1<<MODEM_POWER_ON);
    io_conf.pull_down_en = 0;
    io_conf.pull_up_en = 0;
    gpio_config(&io_conf);

    gpio_set_level(MODEM_PWKEY, 0);
    gpio_set_level(MODEM_RST, 1);
    gpio_set_level(MODEM_POWER_ON, 1);

    vTaskDelay(15000 / portTICK_RATE_MS);

    /* create dte object */
    esp_modem_dte_config_t config = ESP_MODEM_DTE_DEFAULT_CONFIG();
    /* setup UART specific configuration based on kconfig options */
    config.tx_io_num = 27;
    config.rx_io_num = 26;
    config.rts_io_num = CONFIG_EXAMPLE_MODEM_UART_RTS_PIN;
    config.cts_io_num = CONFIG_EXAMPLE_MODEM_UART_CTS_PIN;

    config.rx_buffer_size = CONFIG_EXAMPLE_MODEM_UART_RX_BUFFER_SIZE;
    config.tx_buffer_size = CONFIG_EXAMPLE_MODEM_UART_TX_BUFFER_SIZE;
    config.pattern_queue_size = CONFIG_EXAMPLE_MODEM_UART_PATTERN_QUEUE_SIZE;
    config.event_queue_size = CONFIG_EXAMPLE_MODEM_UART_EVENT_QUEUE_SIZE;
    config.event_task_stack_size = CONFIG_EXAMPLE_MODEM_UART_EVENT_TASK_STACK_SIZE;
    config.event_task_priority = CONFIG_EXAMPLE_MODEM_UART_EVENT_TASK_PRIORITY;
    config.line_buffer_size = CONFIG_EXAMPLE_MODEM_UART_RX_BUFFER_SIZE / 2;

    modem_dte_t *dte = esp_modem_dte_init(&config);
    /* Register event handler */
    ESP_ERROR_CHECK(esp_modem_set_event_handler(dte, modem_event_handler, ESP_EVENT_ANY_ID, NULL));

    // Init netif object
    esp_netif_config_t cfg = ESP_NETIF_DEFAULT_PPP();
    esp_netif_t *esp_netif = esp_netif_new(&cfg);
    assert(esp_netif);

    void *modem_netif_adapter = esp_modem_netif_setup(dte);
    esp_modem_netif_set_default_handlers(modem_netif_adapter, esp_netif);

    while (1) {
        modem_dce_t *dce = NULL;
        /* create dce object */
#if CONFIG_EXAMPLE_MODEM_DEVICE_SIM800
        dce = sim800_init(dte);
#elif CONFIG_EXAMPLE_MODEM_DEVICE_BG96
        dce = bg96_init(dte);
#elif CONFIG_EXAMPLE_MODEM_DEVICE_SIM7600
        dce = sim7600_init(dte);
#else
#error "Unsupported DCE"
#endif
        assert(dce != NULL);
        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 */
        uint32_t 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 */
        uint32_t 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 PPPoS network parameters */
#if !defined(CONFIG_EXAMPLE_MODEM_PPP_AUTH_NONE) && (defined(CONFIG_LWIP_PPP_PAP_SUPPORT) || defined(CONFIG_LWIP_PPP_CHAP_SUPPORT))
        esp_netif_ppp_set_auth(esp_netif, auth_type, CONFIG_EXAMPLE_MODEM_PPP_AUTH_USERNAME, CONFIG_EXAMPLE_MODEM_PPP_AUTH_PASSWORD);
#endif
        /* attach the modem to the network interface */
        esp_netif_attach(esp_netif, modem_netif_adapter);
        /* Wait for IP address */
        xEventGroupWaitBits(event_group, CONNECT_BIT, pdTRUE, pdTRUE, portMAX_DELAY);

        /* Config MQTT */
        esp_mqtt_client_config_t mqtt_config = {
            .uri = BROKER_URL,
            .event_handle = mqtt_event_handler,
        };
        mqtt_client = esp_mqtt_client_init(&mqtt_config);
        esp_mqtt_client_start(mqtt_client);

        xTimer = xTimerCreate
                   ( /* Just a text name, not used by the RTOS
                     kernel. */
                     "Timer",
                     /* The timer period in ticks, must be
                     greater than 0. */
                     10 * 1000 / portTICK_PERIOD_MS,
                     /* The timers will auto-reload themselves
                     when they expire. */
                     pdTRUE,
                     /* The ID is used to store a count of the
                     number of times the timer has expired, which
                     is initialised to 0. */
                     ( void * ) 0,
                     /* Each timer calls the same callback when
                     it expires. */
                     vTimerCallback
                   );

        xTimerStart(xTimer, 0);

        xEventGroupWaitBits(event_group, GOT_DATA_BIT, pdTRUE, pdTRUE, portMAX_DELAY);
        esp_mqtt_client_destroy(mqtt_client);

        /* Exit PPP mode */
        ESP_ERROR_CHECK(esp_modem_stop_ppp(dte));

        xEventGroupWaitBits(event_group, STOP_BIT, pdTRUE, pdTRUE, portMAX_DELAY);

        /* Power down module */
        ESP_ERROR_CHECK(dce->power_down(dce));
        ESP_LOGI(TAG, "Power down");
        ESP_ERROR_CHECK(dce->deinit(dce));

        ESP_LOGI(TAG, "Restart after 60 seconds");
        vTaskDelay(pdMS_TO_TICKS(60000));
    }

    /* Unregister events, destroy the netif adapter and destroy its esp-netif instance */
    esp_modem_netif_clear_default_handlers(modem_netif_adapter);
    esp_modem_netif_teardown(modem_netif_adapter);
    esp_netif_destroy(esp_netif);

    ESP_ERROR_CHECK(dte->deinit(dte));
}

In the process of trying to isolate the problem I added some debug code to the modem code:

diff --git a/examples/protocols/pppos_client/components/modem/src/esp_modem.c b/examples/protocols/pppos_client/components/modem/src/esp_modem.c
index 27d25c2ca..6673c50da 100644
--- a/examples/protocols/pppos_client/components/modem/src/esp_modem.c
+++ b/examples/protocols/pppos_client/components/modem/src/esp_modem.c
@@ -136,6 +136,14 @@ static void esp_handle_uart_pattern(esp_modem_dte_t *esp_dte)
         if (read_len) {
             /* make sure the line is a standard string */
             esp_dte->buffer[read_len] = '\0';
+
+            printf("Received pattern data from Modem: %.*s, %d Bytes \n", read_len, esp_dte->buffer, read_len);
+
+            for(int i = 0; i < read_len; i++) {
+                printf("%X ", esp_dte->buffer[i]);
+            }
+            printf("\n");
+
             /* Send new line to handle */
             esp_dte_handle_line(esp_dte);
         } else {
@@ -167,6 +175,13 @@ static void esp_handle_uart_data(esp_modem_dte_t *esp_dte)
     length = uart_read_bytes(esp_dte->uart_port, esp_dte->buffer, length, portMAX_DELAY);
     /* pass the input data to configured callback */
     if (length) {
+        printf("Received data from Modem: %.*s, %d Bytes \n", length, esp_dte->buffer, length);
+
+        for(int i = 0; i < length; i++) {
+            printf("%X ", esp_dte->buffer[i]);
+        }
+        printf("\n");
+
         esp_dte->receive_cb(esp_dte->buffer, length, esp_dte->receive_cb_ctx);
     }
 }
@@ -494,7 +509,7 @@ esp_err_t esp_modem_start_ppp(modem_dte_t *dte)
     MODEM_CHECK(dce, "DTE has not yet bind with DCE", err);
     esp_modem_dte_t *esp_dte = __containerof(dte, esp_modem_dte_t, parent);
     /* Set PDP Context */
-    MODEM_CHECK(dce->define_pdp_context(dce, 1, "IP", CONFIG_EXAMPLE_COMPONENT_MODEM_APN) == ESP_OK, "set MODEM APN failed", err);
+    MODEM_CHECK(dce->define_pdp_context(dce, 1, "IP", "TM") == ESP_OK, "set MODEM APN failed", err);
     /* Enter PPP mode */
     MODEM_CHECK(dte->change_mode(dte, MODEM_PPP_MODE) == ESP_OK, "enter ppp mode failed", err);
MrCurio commented 3 years ago

Hello @berkutta , From the error you are getting (-1), it seems you are running out of memory.

Take a look at the line i am pointing at:

err_t
pppos_input_tcpip(ppp_pcb *ppp, u8_t *s, int l)
{
  struct pbuf *p;
  err_t err;

  p = pbuf_alloc(PBUF_RAW, l, PBUF_POOL);
  if (!p) {
    return ERR_MEM; ---------------------------------> ERR_MEM error corresponds to -1 in err.h
  }
  pbuf_take(p, s, l);

  err = tcpip_inpkt(p, ppp_netif(ppp), pppos_input_sys);
  if (err != ERR_OK) {
     pbuf_free(p);
  }
  return err;
}

Since your pppos_input_tcpip function is returning -1, it means you ran out of memory.

Be careful with initializing multiple instances and not freeing them. I can see that in every loop you create a new instance by calling xTimerCreate. This function does not override the previous timer, instead it allocates space for another one and returns the handle.

You should only instance one timer before the while. Please give it a try and let me know. If this is not the issue, check other memory leaks that may be present in your code.

When you confirm, please close this issue! Thanks!

berkutta commented 3 years ago

Hi @MrCurio

Thanks for the code review. I think you are on a very hot track.

xTimerCreate just gets called once, it's within a loop but it never loops as it waits forever for GOT_DATA_BIT which doesn't get set any more.

But my big flaw is after sending the MQTT Message. I correctly delete the cJSON object with cJSON_Delete(root), but afterwards I try to free the cJSON object with free(root) which is wrong. Instead I should return cJSON_PrintUnformatted(root) to a pointer which I can then free after usage. Otherwise, cJSON allocates a string on every run without ever freeing it..

TL;DR: RTFM on cJSON, the updated code is now running with some additional code to monitor the heap usage. Will report back in a few days if it now runs stable.

Updated function:

void vTimerCallback( TimerHandle_t xTimer )
{
    static uint32_t loop = 0;

    cJSON *root = cJSON_CreateObject();
    cJSON *device = cJSON_CreateObject();

    cJSON_AddNumberToObject(device, "loop", loop);
    cJSON_AddNumberToObject(device, "heap", esp_get_free_heap_size());

    cJSON_AddItemToObject(root, "device", device);

    char publish_topic[60];

    sprintf(publish_topic, "/topic/esp-%d/status", 1234);

    char *payload = cJSON_PrintUnformatted(root);
    esp_mqtt_client_publish(mqtt_client, publish_topic, payload, 0, 0, 0);

    printf("Publishing to topic %s \n", publish_topic);

    cJSON_Delete(root);
    free(payload);

    loop++;
}
lhespress commented 3 years ago

@berkutta

I suggest that the code as follows:

static char *pppos_publish_payload(uint32_t loop) 
{
    cJSON *root = cJSON_CreateObject();
    cJSON *device = cJSON_CreateObject();

    cJSON_AddNumberToObject(device, "loop", loop);

    cJSON_AddItemToObject(root, "device", device);

    char *payload = cJSON_PrintUnformatted(root);
    cJSON_Delete(root);

    return payload;
} 

void vTimerCallback( TimerHandle_t xTimer )
{
    static uint32_t loop = 0;

    char *paylaod = pppos_publish_payload(loop);
    char publish_topic[60];
    sprintf(publish_topic, "/topic/esp-%d/status", 1234);

    esp_mqtt_client_publish(mqtt_client, publish_topic, paylaod, strlen(paylaod), 0, 0);

    printf("Publishing to topic %s \n", publish_topic);
    free(payload);
    loop++;
}

You‘ll remember to free the heap.

berkutta commented 3 years ago

Works fine now, thanks @MrCurio!

yeah, thats a nice way of handling it, will remember that @lhespress