From 84039dc77d1939a681879a057ce6fe959a5bc670 Mon Sep 17 00:00:00 2001 From: David Cermak Date: Mon, 26 Oct 2020 11:50:06 +0100 Subject: [PATCH] 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 --- .../components/modem/include/esp_modem.h | 11 ++ .../components/modem/include/esp_modem_dte.h | 4 +- .../pppos_client/components/modem/src/bg96.c | 22 ++- .../components/modem/src/esp_modem.c | 147 +++++++++++++++--- .../components/modem/src/esp_modem_netif.c | 20 +++ .../components/modem/src/sim800.c | 22 ++- 6 files changed, 196 insertions(+), 30 deletions(-) diff --git a/examples/protocols/pppos_client/components/modem/include/esp_modem.h b/examples/protocols/pppos_client/components/modem/include/esp_modem.h index 6b6185fc66..4440b7a5a9 100644 --- a/examples/protocols/pppos_client/components/modem/include/esp_modem.h +++ b/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 diff --git a/examples/protocols/pppos_client/components/modem/include/esp_modem_dte.h b/examples/protocols/pppos_client/components/modem/include/esp_modem_dte.h index 6664560da6..f87600e89b 100644 --- a/examples/protocols/pppos_client/components/modem/include/esp_modem_dte.h +++ b/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; /** diff --git a/examples/protocols/pppos_client/components/modem/src/bg96.c b/examples/protocols/pppos_client/components/modem/src/bg96.c index 2625613ccb..4aa82ae884 100644 --- a/examples/protocols/pppos_client/components/modem/src/bg96.c +++ b/examples/protocols/pppos_client/components/modem/src/bg96.c @@ -294,16 +294,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; 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 928fbbfa51..602caf8f32 100644 --- a/examples/protocols/pppos_client/components/modem/src/esp_modem.c +++ b/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 */ @@ -62,6 +63,21 @@ typedef struct { int pattern_queue_size; /*!< UART pattern queue size */ } esp_modem_dte_t; +/** + * @brief Returns true if the supplied string contains only CR or LF + * + * @param str string to check + * @param len length of string + */ +static inline bool is_only_cr_lf(const char *str, uint32_t len) +{ + for (int i=0; iparent.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 (strlen(line) > 2) { - 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 (len > 2 && !is_only_cr_lf(line, len)) { + 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; } /** @@ -108,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') */ @@ -126,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); } } @@ -138,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 */ @@ -165,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); @@ -197,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); } @@ -245,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; @@ -304,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; } @@ -345,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 */ @@ -432,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 @@ -445,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); @@ -495,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; +} diff --git a/examples/protocols/pppos_client/components/modem/src/esp_modem_netif.c b/examples/protocols/pppos_client/components/modem/src/esp_modem_netif.c index e04e822086..bcddf66867 100644 --- a/examples/protocols/pppos_client/components/modem/src/esp_modem_netif.c +++ b/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); } diff --git a/examples/protocols/pppos_client/components/modem/src/sim800.c b/examples/protocols/pppos_client/components/modem/src/sim800.c index 05151b7bfe..d2ced136a9 100644 --- a/examples/protocols/pppos_client/components/modem/src/sim800.c +++ b/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;