esp_modem: Fixed race condition on exiting PPP mode

esp_modem_stop_ppp() stops both ppp netif and switches the modem back to
command mode. IF these two actions are not synchronised, we might
experience issues of
* active PPP session trying to send/receive uart-data
* command mode already active before modem switched to it
both resulting in crashes.
Fixed by introducing the transition mode and running these actions in sequence
* set esp-modem to transition mode
* enter command mode, wait for the reply or re-sync
* close the PPP netif
* wait until the netif closes
Other fixes include ignoring certain events if modem component not ready
or not in appropriate mode:
* ignoring all UART events comming from DTE with no DCE attached
* ignore pattern detection in PPP mode

Closes https://github.com/espressif/esp-idf/issues/6013
Closes https://github.com/espressif/esp-idf/issues/5737
Closes https://github.com/espressif/esp-idf/issues/6024
Closes https://github.com/espressif/esp-idf/issues/6058
Closes https://github.com/espressif/esp-idf/issues/5563
Closes https://github.com/espressif/esp-idf/issues/5695
Closes https://github.com/espressif/esp-idf/issues/5633
Closes https://github.com/espressif/esp-idf/issues/4482
Related https://github.com/espressif/esp-idf/pull/4849
Related https://github.com/espressif/esp-idf/pull/4653

examples/protocols/pppos_client/components/modem/include/esp_modem.h

@@ -158,6 +158,17 @@ esp_err_t esp_modem_stop_ppp(modem_dte_t *dte);
  */
 esp_err_t esp_modem_set_rx_cb(modem_dte_t *dte, esp_modem_on_receive receive_cb, void *receive_cb_ctx);
 
+/**
+ * @brief Notify the modem, that ppp netif has closed
+ *
+ * @note This API should only be used internally by the modem-netif layer
+ *
+ * @param dte ESP Modem DTE object
+ *
+ * @return ESP_OK on success
+ */
+esp_err_t esp_modem_notify_ppp_netif_closed(modem_dte_t *dte);
+
 #ifdef __cplusplus
 }
 #endif

examples/protocols/pppos_client/components/modem/include/esp_modem_dte.h

@@ -30,7 +30,9 @@ typedef struct modem_dce modem_dce_t;
  */
 typedef enum {
     MODEM_COMMAND_MODE = 0, /*!< Command Mode */
-    MODEM_PPP_MODE          /*!< PPP Mode */
+    MODEM_PPP_MODE,         /*!< PPP Mode */
+    MODEM_TRANSITION_MODE   /*!< Transition Mode between data and command mode indicating that
+                                 the modem is not yet ready for sending commands nor data */
 } modem_mode_t;
 
 /**

examples/protocols/pppos_client/components/modem/src/bg96.c

@@ -273,16 +273,32 @@ static esp_err_t bg96_set_working_mode(modem_dce_t *dce, modem_mode_t mode)
     modem_dte_t *dte = dce->dte;
     switch (mode) {
     case MODEM_COMMAND_MODE:
+        vTaskDelay(pdMS_TO_TICKS(1000)); // spec: 1s delay for the modem to recognize the escape sequence
         dce->handle_line = bg96_handle_exit_data_mode;
-        DCE_CHECK(dte->send_cmd(dte, "+++", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) == ESP_OK, "send command failed", err);
-        DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter command mode failed", err);
+        if (dte->send_cmd(dte, "+++", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) != ESP_OK) {
+            // "+++" Could fail if we are already in the command mode.
+            // in that case we ignore the timeout and re-sync the modem
+            ESP_LOGI(DCE_TAG, "Sending \"+++\" command failed");
+            dce->handle_line = esp_modem_dce_handle_response_default;
+            DCE_CHECK(dte->send_cmd(dte, "AT\r", MODEM_COMMAND_TIMEOUT_DEFAULT) == ESP_OK, "send command failed", err);
+            DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "sync failed", err);
+        } else {
+            DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter command mode failed", err);
+        }
         ESP_LOGD(DCE_TAG, "enter command mode ok");
         dce->mode = MODEM_COMMAND_MODE;
         break;
     case MODEM_PPP_MODE:
         dce->handle_line = bg96_handle_atd_ppp;
         DCE_CHECK(dte->send_cmd(dte, "ATD*99***1#\r", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) == ESP_OK, "send command failed", err);
-        DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter ppp mode failed", err);
+        if (dce->state != MODEM_STATE_SUCCESS) {
+            // Initiate PPP mode could fail, if we've already "dialed" the data call before.
+            // in that case we retry with "ATO" to just resume the data mode
+            ESP_LOGD(DCE_TAG, "enter ppp mode failed, retry with ATO");
+            dce->handle_line = bg96_handle_atd_ppp;
+            DCE_CHECK(dte->send_cmd(dte, "ATO\r", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) == ESP_OK, "send command failed", err);
+            DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter ppp mode failed", err);
+        }
         ESP_LOGD(DCE_TAG, "enter ppp mode ok");
         dce->mode = MODEM_PPP_MODE;
         break;

examples/protocols/pppos_client/components/modem/src/esp_modem.c

@@ -55,6 +55,7 @@ typedef struct {
     esp_event_loop_handle_t event_loop_hdl; /*!< Event loop handle */
     TaskHandle_t uart_event_task_hdl;       /*!< UART event task handle */
     SemaphoreHandle_t process_sem;          /*!< Semaphore used for indicating processing status */
+    SemaphoreHandle_t   exit_sem;           /*!< Semaphore used for indicating PPP mode has stopped */
     modem_dte_t parent;                     /*!< DTE interface that should extend */
     esp_modem_on_receive receive_cb;        /*!< ptr to data reception */
     void *receive_cb_ctx;                   /*!< ptr to rx fn context data */
@@ -97,22 +98,28 @@ esp_err_t esp_modem_set_rx_cb(modem_dte_t *dte, esp_modem_on_receive receive_cb,
  */
 static esp_err_t esp_dte_handle_line(esp_modem_dte_t *esp_dte)
 {
+    esp_err_t err = ESP_FAIL;
     modem_dce_t *dce = esp_dte->parent.dce;
     MODEM_CHECK(dce, "DTE has not yet bind with DCE", err);
     const char *line = (const char *)(esp_dte->buffer);
     size_t len = strlen(line);
     /* Skip pure "\r\n" lines */
     if (len > 2 && !is_only_cr_lf(line, len)) {
-        MODEM_CHECK(dce->handle_line, "no handler for line", err_handle);
-        MODEM_CHECK(dce->handle_line(dce, line) == ESP_OK, "handle line failed", err_handle);
+        if (dce->handle_line == NULL) {
+            /* Received an asynchronous line, but no handler waiting this this */
+            ESP_LOGD(MODEM_TAG, "No handler for line: %s", line);
+            err = ESP_OK; /* Not an error, just propagate the line to user handler */
+            goto post_event_unknown;
+        }
+        MODEM_CHECK(dce->handle_line(dce, line) == ESP_OK, "handle line failed", post_event_unknown);
     }
     return ESP_OK;
-err_handle:
+post_event_unknown:
     /* Send ESP_MODEM_EVENT_UNKNOWN signal to event loop */
     esp_event_post_to(esp_dte->event_loop_hdl, ESP_MODEM_EVENT, ESP_MODEM_EVENT_UNKNOWN,
                       (void *)line, strlen(line) + 1, pdMS_TO_TICKS(100));
 err:
-    return ESP_FAIL;
+    return err;
 }
 
 /**
@@ -124,6 +131,15 @@ static void esp_handle_uart_pattern(esp_modem_dte_t *esp_dte)
 {
     int pos = uart_pattern_pop_pos(esp_dte->uart_port);
     int read_len = 0;
+
+    if (esp_dte->parent.dce->mode == MODEM_PPP_MODE) {
+        ESP_LOGD(MODEM_TAG, "Pattern event in PPP mode ignored");
+        // Ignore potential pattern detection events in PPP mode
+        // Note 1: the interrupt is disabled, but some events might still be pending
+        // Note 2: checking the mode *after* uart_pattern_pop_pos() to consume the event
+        return;
+    }
+
     if (pos != -1) {
         if (pos < esp_dte->line_buffer_size - 1) {
             /* read one line(include '\n') */
@@ -142,7 +158,14 @@ static void esp_handle_uart_pattern(esp_modem_dte_t *esp_dte)
             ESP_LOGE(MODEM_TAG, "uart read bytes failed");
         }
     } else {
-        ESP_LOGW(MODEM_TAG, "Pattern Queue Size too small");
+        size_t length = 0;
+        uart_get_buffered_data_len(esp_dte->uart_port, &length);
+        if (length) {
+            ESP_LOGD(MODEM_TAG, "Pattern not found in the pattern queue, uart data length = %d", length);
+            length = MIN(esp_dte->line_buffer_size-1, length);
+            length = uart_read_bytes(esp_dte->uart_port, esp_dte->buffer, length, portMAX_DELAY);
+            ESP_LOG_BUFFER_HEXDUMP("esp-modem-pattern: debug_data", esp_dte->buffer, length, ESP_LOG_DEBUG);
+        }
         uart_flush(esp_dte->uart_port);
     }
 }
@@ -154,15 +177,41 @@ static void esp_handle_uart_pattern(esp_modem_dte_t *esp_dte)
  */
 static void esp_handle_uart_data(esp_modem_dte_t *esp_dte)
 {
-    if (esp_dte->parent.dce->mode != MODEM_PPP_MODE) {
-        ESP_LOGE(MODEM_TAG, "Error: Got data event in PPP mode");
-        /* pattern detection mode -> ignore date event on uart
-         * (should never happen, but if it does, we could still
-         * read the valid data once pattern detect event fired) */
-        return;
-    }
     size_t length = 0;
     uart_get_buffered_data_len(esp_dte->uart_port, &length);
+    if (esp_dte->parent.dce->mode != MODEM_PPP_MODE && length) {
+        // Check if matches the pattern to process the data as pattern
+        int pos = uart_pattern_get_pos(esp_dte->uart_port);
+        if (pos > -1) {
+            esp_handle_uart_pattern(esp_dte);
+            return;
+        }
+        // Read the data and process it using `handle_line` logic
+        length = MIN(esp_dte->line_buffer_size-1, length);
+        length = uart_read_bytes(esp_dte->uart_port, esp_dte->buffer, length, portMAX_DELAY);
+        esp_dte->buffer[length] = '\0';
+        if (strchr((char*)esp_dte->buffer, '\n') == NULL) {
+            size_t max = esp_dte->line_buffer_size-1;
+            size_t bytes;
+            // if pattern not found in the data,
+            // continue reading as long as the modem is in MODEM_STATE_PROCESSING, checking for the pattern
+            while (length < max && esp_dte->buffer[length-1] != '\n' &&
+                   esp_dte->parent.dce->state == MODEM_STATE_PROCESSING) {
+                bytes = uart_read_bytes(esp_dte->uart_port,
+                                        esp_dte->buffer + length, 1, pdMS_TO_TICKS(100));
+                length += bytes;
+                ESP_LOGV("esp-modem: debug_data", "Continuous read in non-data mode: length: %d char: %x", length, esp_dte->buffer[length-1]);
+            }
+            esp_dte->buffer[length] = '\0';
+        }
+        ESP_LOG_BUFFER_HEXDUMP("esp-modem: debug_data", esp_dte->buffer, length, ESP_LOG_DEBUG);
+        if (esp_dte->parent.dce->handle_line) {
+            /* Send new line to handle if handler registered */
+            esp_dte_handle_line(esp_dte);
+        }
+        return;
+    }
+
     length = MIN(esp_dte->line_buffer_size, length);
     length = uart_read_bytes(esp_dte->uart_port, esp_dte->buffer, length, portMAX_DELAY);
     /* pass the input data to configured callback */
@@ -181,7 +230,20 @@ static void uart_event_task_entry(void *param)
     esp_modem_dte_t *esp_dte = (esp_modem_dte_t *)param;
     uart_event_t event;
     while (1) {
+        /* Drive the event loop */
+        esp_event_loop_run(esp_dte->event_loop_hdl, pdMS_TO_TICKS(0));
+
+        /* Process UART events */
         if (xQueueReceive(esp_dte->event_queue, &event, pdMS_TO_TICKS(100))) {
+            if (esp_dte->parent.dce == NULL) {
+                ESP_LOGD(MODEM_TAG, "Ignore UART event for DTE with no DCE attached");
+                // No action on any uart event with null DCE.
+                // This might happen before DCE gets initialized and attached to running DTE,
+                // or after destroying the DCE when DTE is up and gets a data event.
+                uart_flush(esp_dte->uart_port);
+                continue;
+            }
+
             switch (event.type) {
             case UART_DATA:
                 esp_handle_uart_data(esp_dte);
@@ -213,8 +275,6 @@ static void uart_event_task_entry(void *param)
                 break;
             }
         }
-        /* Drive the event loop */
-        esp_event_loop_run(esp_dte->event_loop_hdl, pdMS_TO_TICKS(50));
     }
     vTaskDelete(NULL);
 }
@@ -261,6 +321,10 @@ static int esp_modem_dte_send_data(modem_dte_t *dte, const char *data, uint32_t
 {
     MODEM_CHECK(data, "data is NULL", err);
     esp_modem_dte_t *esp_dte = __containerof(dte, esp_modem_dte_t, parent);
+    if (esp_dte->parent.dce->mode == MODEM_TRANSITION_MODE) {
+        ESP_LOGD(MODEM_TAG, "Not sending data in transition mode");
+        return -1;
+    }
     return uart_write_bytes(esp_dte->uart_port, data, length);
 err:
     return -1;
@@ -320,24 +384,29 @@ static esp_err_t esp_modem_dte_change_mode(modem_dte_t *dte, modem_mode_t new_mo
     modem_dce_t *dce = dte->dce;
     MODEM_CHECK(dce, "DTE has not yet bind with DCE", err);
     esp_modem_dte_t *esp_dte = __containerof(dte, esp_modem_dte_t, parent);
-    MODEM_CHECK(dce->mode != new_mode, "already in mode: %d", err, new_mode);
+    modem_mode_t current_mode = dce->mode;
+    MODEM_CHECK(current_mode != new_mode, "already in mode: %d", err, new_mode);
+    dce->mode = MODEM_TRANSITION_MODE;  // mode switching will be finished in set_working_mode() on success
+                                        // (or restored on failure)
     switch (new_mode) {
     case MODEM_PPP_MODE:
-        MODEM_CHECK(dce->set_working_mode(dce, new_mode) == ESP_OK, "set new working mode:%d failed", err, new_mode);
+        MODEM_CHECK(dce->set_working_mode(dce, new_mode) == ESP_OK, "set new working mode:%d failed", err_restore_mode, new_mode);
         uart_disable_pattern_det_intr(esp_dte->uart_port);
         uart_enable_rx_intr(esp_dte->uart_port);
         break;
     case MODEM_COMMAND_MODE:
+        MODEM_CHECK(dce->set_working_mode(dce, new_mode) == ESP_OK, "set new working mode:%d failed", err_restore_mode, new_mode);
         uart_disable_rx_intr(esp_dte->uart_port);
         uart_flush(esp_dte->uart_port);
         uart_enable_pattern_det_baud_intr(esp_dte->uart_port, '\n', 1, MIN_PATTERN_INTERVAL, MIN_POST_IDLE, MIN_PRE_IDLE);
         uart_pattern_queue_reset(esp_dte->uart_port, esp_dte->pattern_queue_size);
-        MODEM_CHECK(dce->set_working_mode(dce, new_mode) == ESP_OK, "set new working mode:%d failed", err, new_mode);
         break;
     default:
         break;
     }
     return ESP_OK;
+err_restore_mode:
+    dce->mode = current_mode;
 err:
     return ESP_FAIL;
 }
@@ -361,8 +430,9 @@ static esp_err_t esp_modem_dte_deinit(modem_dte_t *dte)
     esp_modem_dte_t *esp_dte = __containerof(dte, esp_modem_dte_t, parent);
     /* Delete UART event task */
     vTaskDelete(esp_dte->uart_event_task_hdl);
-    /* Delete semaphore */
+    /* Delete semaphores */
     vSemaphoreDelete(esp_dte->process_sem);
+    vSemaphoreDelete(esp_dte->exit_sem);
     /* Delete event loop */
     esp_event_loop_delete(esp_dte->event_loop_hdl);
     /* Uninstall UART Driver */
@@ -448,7 +518,10 @@ modem_dte_t *esp_modem_dte_init(const esp_modem_dte_config_t *config)
     MODEM_CHECK(esp_event_loop_create(&loop_args, &esp_dte->event_loop_hdl) == ESP_OK, "create event loop failed", err_eloop);
     /* Create semaphore */
     esp_dte->process_sem = xSemaphoreCreateBinary();
-    MODEM_CHECK(esp_dte->process_sem, "create process semaphore failed", err_sem);
+    MODEM_CHECK(esp_dte->process_sem, "create process semaphore failed", err_sem1);
+    esp_dte->exit_sem = xSemaphoreCreateBinary();
+    MODEM_CHECK(esp_dte->exit_sem, "create exit semaphore failed", err_sem);
+
     /* Create UART Event task */
     BaseType_t ret = xTaskCreate(uart_event_task_entry,             //Task Entry
                                  "uart_event",              //Task Name
@@ -461,8 +534,10 @@ modem_dte_t *esp_modem_dte_init(const esp_modem_dte_config_t *config)
     return &(esp_dte->parent);
     /* Error handling */
 err_tsk_create:
-    vSemaphoreDelete(esp_dte->process_sem);
+    vSemaphoreDelete(esp_dte->exit_sem);
 err_sem:
+    vSemaphoreDelete(esp_dte->process_sem);
+err_sem1:
     esp_event_loop_delete(esp_dte->event_loop_hdl);
 err_eloop:
     uart_disable_pattern_det_intr(esp_dte->uart_port);
@@ -511,13 +586,23 @@ esp_err_t esp_modem_stop_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);
 
-    /* post PPP mode stopped event */
-    esp_event_post_to(esp_dte->event_loop_hdl, ESP_MODEM_EVENT, ESP_MODEM_EVENT_PPP_STOP, NULL, 0, 0);
     /* Enter command mode */
     MODEM_CHECK(dte->change_mode(dte, MODEM_COMMAND_MODE) == ESP_OK, "enter command mode failed", err);
+    /* post PPP mode stopped event */
+    esp_event_post_to(esp_dte->event_loop_hdl, ESP_MODEM_EVENT, ESP_MODEM_EVENT_PPP_STOP, NULL, 0, 0);
     /* Hang up */
     MODEM_CHECK(dce->hang_up(dce) == ESP_OK, "hang up failed", err);
+    /* wait for the PPP mode to exit gracefully */
+    if (xSemaphoreTake(esp_dte->exit_sem, pdMS_TO_TICKS(20000)) != pdTRUE) {
+        ESP_LOGW(MODEM_TAG, "Failed to exit the PPP mode gracefully");
+    }
     return ESP_OK;
 err:
     return ESP_FAIL;
 }
+
+esp_err_t esp_modem_notify_ppp_netif_closed(modem_dte_t *dte)
+{
+    esp_modem_dte_t *esp_dte = __containerof(dte, esp_modem_dte_t, parent);
+    return xSemaphoreGive(esp_dte->exit_sem) == pdTRUE ? ESP_OK : ESP_FAIL;
+}

examples/protocols/pppos_client/components/modem/src/esp_modem_netif.c

@@ -12,6 +12,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 #include "esp_netif.h"
+#include "esp_netif_ppp.h"
 #include "esp_modem.h"
 #include "esp_log.h"
 
@@ -25,6 +26,16 @@ typedef struct esp_modem_netif_driver_s {
     modem_dte_t            *dte;        /*!< ptr to the esp_modem objects (DTE) */
 } esp_modem_netif_driver_t;
 
+static void on_ppp_changed(void *arg, esp_event_base_t event_base,
+                           int32_t event_id, void *event_data)
+{
+    modem_dte_t *dte = arg;
+    if (event_id < NETIF_PP_PHASE_OFFSET) {
+        ESP_LOGI(TAG, "PPP state changed event %d", event_id);
+        // only notify the modem on state/error events, ignoring phase transitions
+        esp_modem_notify_ppp_netif_closed(dte);
+    }
+}
 /**
  * @brief Transmit function called from esp_netif to output network stack data
  *
@@ -66,6 +77,15 @@ static esp_err_t esp_modem_post_attach_start(esp_netif_t * esp_netif, void * arg
     };
     driver->base.netif = esp_netif;
     ESP_ERROR_CHECK(esp_netif_set_driver_config(esp_netif, &driver_ifconfig));
+
+    // enable both events, so we could notify the modem layer if an error occurred/state changed
+    esp_netif_ppp_config_t ppp_config = {
+            .ppp_error_event_enabled = true,
+            .ppp_phase_event_enabled = true
+    };
+    esp_netif_ppp_set_params(esp_netif, &ppp_config);
+
+    ESP_ERROR_CHECK(esp_event_handler_register(NETIF_PPP_STATUS, ESP_EVENT_ANY_ID, &on_ppp_changed, dte));
     return esp_modem_start_ppp(dte);
 }
 

examples/protocols/pppos_client/components/modem/src/sim800.c

@@ -294,15 +294,31 @@ static esp_err_t sim800_set_working_mode(modem_dce_t *dce, modem_mode_t mode)
     switch (mode) {
     case MODEM_COMMAND_MODE:
         dce->handle_line = sim800_handle_exit_data_mode;
-        DCE_CHECK(dte->send_cmd(dte, "+++", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) == ESP_OK, "send command failed", err);
-        DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter command mode failed", err);
+        vTaskDelay(pdMS_TO_TICKS(1000)); // spec: 1s delay for the modem to recognize the escape sequence
+        if (dte->send_cmd(dte, "+++", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) != ESP_OK) {
+            // "+++" Could fail if we are already in the command mode.
+            // in that case we ignore the timeout and re-sync the modem
+            ESP_LOGI(DCE_TAG, "Sending \"+++\" command failed");
+            dce->handle_line = esp_modem_dce_handle_response_default;
+            DCE_CHECK(dte->send_cmd(dte, "AT\r", MODEM_COMMAND_TIMEOUT_DEFAULT) == ESP_OK, "send command failed", err);
+            DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "sync failed", err);
+        } else {
+            DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter command mode failed", err);
+        }
         ESP_LOGD(DCE_TAG, "enter command mode ok");
         dce->mode = MODEM_COMMAND_MODE;
         break;
     case MODEM_PPP_MODE:
         dce->handle_line = sim800_handle_atd_ppp;
         DCE_CHECK(dte->send_cmd(dte, "ATD*99#\r", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) == ESP_OK, "send command failed", err);
-        DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter ppp mode failed", err);
+            if (dce->state != MODEM_STATE_SUCCESS) {
+                // Initiate PPP mode could fail, if we've already "dialed" the data call before.
+                // in that case we retry with "ATO" to just resume the data mode
+                ESP_LOGD(DCE_TAG, "enter ppp mode failed, retry with ATO");
+                dce->handle_line = sim800_handle_atd_ppp;
+                DCE_CHECK(dte->send_cmd(dte, "ATO\r", MODEM_COMMAND_TIMEOUT_MODE_CHANGE) == ESP_OK, "send command failed", err);
+                DCE_CHECK(dce->state == MODEM_STATE_SUCCESS, "enter ppp mode failed", err);
+            }
         ESP_LOGD(DCE_TAG, "enter ppp mode ok");
         dce->mode = MODEM_PPP_MODE;
         break;