esp_modem regression from 1.0.1 to 1.0.3: fails to acknowledge basic AT commands via USB (IDFGH-11318)

[DaStoned]

Answers checklist.

• [X] I have read the documentation for esp-protocols components and the issue is not addressed there.
• [X] I have updated my esp-protocols branch (master or release) to the latest version and checked that the issue is present there.
• [X] I have searched the issue tracker for a similar issue and not found a similar issue.

General issue report

I'm issuing basic AT queries to a SimCom SIM7070G module connected via USB - get module name, firmware revision, battery level etc - using the C++ API. They were working fine with esp_modem version 1.0.1 and started to fail rather spectacularly in 1.0.3.

// Run a modem query with a few retries
// Adapted from https://stackoverflow.com/a/76233658/9989141
template <typename Callable, typename ...ArgsT>
constexpr decltype(auto) retryQuery(size_t maxRetries, Callable&& func, ArgsT&&... args) {
    size_t retries = 0;
    auto ret = invoke(forward<Callable>(func), forward<ArgsT>(args)...);
    while (command_result::OK != ret && retries++ < maxRetries) {
        tag_debug("Cmd result: %s (%u) (retry %u/%u)", modem_err_to_name(ret), static_cast<unsigned int>(ret), retries, maxRetries);
        ret = invoke(forward<Callable>(func), forward<ArgsT>(args)...);
    }
    return ret;
}

...
    _modem_config = ESP_MODEM_DCE_DEFAULT_CONFIG("terminal.apn");
    _netif_ppp_config = ESP_NETIF_DEFAULT_PPP();
    _esp_netif = esp_netif_new(&_netif_ppp_config);
    if(!_esp_netif) {
        tag_error("Fail create PPP netif");
        return false;
    }

    struct esp_modem_usb_term_config usb_config =
        ESP_MODEM_DEFAULT_USB_CONFIG(0x1e0e, 0x9206, 2);
    usb_config.timeout_ms = 10000;
    esp_modem_dte_config_t dte_usb_config =
        ESP_MODEM_DTE_DEFAULT_USB_CONFIG(usb_config);
    dte_usb_config.dte_buffer_size = 1536; // Must fit PPPoS MTU (1500 B?)

    _uart_dte = create_usb_dte(&dte_usb_config);
    if (!_uart_dte) {
        tag_error("Fail create USB DTE");
        return false;
    }

    _uart_dte->set_error_cb(onUsbTerminalErr);
    _modem = create_SIM7070_dce(&_modem_config, _uart_dte, _esp_netif);
    if (!_modem) {
        tag_error("Fail create SIM7070 modem");
        return false;
    }

    string strOut;
    command_result cmdRes;

    // Module may take time starting from cold boot. Wait until responsive.
    cmdRes = retryQuery(100, [this](string& out)->command_result {return _modem->at("AT+CGMI", out, GSM_CMD_TIMEOUT_MS);}, strOut);
    if (command_result::OK == cmdRes) {
        tag_info("GSM manufacturer: [%s]", strOut.c_str());
    } else {
        tag_error("Fail query GSM manufacturer");
        return false; // Looks like GSM is not responding. Call it a failure.
    }

    cmdRes = retryQuery(10, [this](string& out)->command_result {return _modem->get_module_name(out);}, strOut);
    if (command_result::OK == cmdRes) {
        tag_info("GSM HW model: [%s]", strOut.c_str());
    } else {
        tag_error("Fail query GSM HW model: %s", modem_err_to_name(cmdRes));
    }

With 1.0.1 it works OK:

D (18117) usb_terminal: USB Host installed
D (18527) usb_terminal: 0x3fcc726c   41 54 2b 43 47 4d 49 0d                           |AT+CGMI.|
D (18527) usb_terminal: 0x3fcb822c   41 54 2b 43 47 4d 49 0d                           |AT+CGMI.|
D (18537) usb_terminal: 0x3fcb8234   0d 0a 53 49 4d 43 4f 4d  5f 4c 74 64 0d 0a 0d 0a  |..SIMCOM_Ltd....|
D (18547) usb_terminal: 0x3fcb8244   4f 4b 0d 0a                                       |OK..|
I (18557) gsm_modem: GSM manufacturer: [SIMCOM_Ltd]
D (18567) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (18567) usb_terminal: 0x3fcb822c   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (18577) usb_terminal: 0x3fcb8234   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (18587) usb_terminal: 0x3fcb8244   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
I (18607) gsm_modem: GSM HW model: [SIMCOM_SIM7070]

With 1.0.3 there are extremely frequent failures. The response from e.g. get_module_name() is command_result::FAIL and I just keep retrying until it gets a response. Sometimes even 10 retries aren't enough :|

D (18146) usb_terminal: USB Host installed
D (18586) command_lib: generic_get_string
D (18586) command_lib: generic_get_string
D (18586) usb_terminal: 0x3fcc726c   41 54 2b 43 47 4d 49 0d                           |AT+CGMI.|
D (18596) usb_terminal: 0x3fcb822c   41 54 2b 43 47 4d 49 0d                           |AT+CGMI.|
D (18596) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 4c 74 64 0d 0a 0d 0a  |..SIMCOM_Ltd....|
D (18606) usb_terminal: 0x3fcb823c   4f 4b 0d 0a                                       |OK..|
D (18616) gsm_modem: Cmd result: ERROR (1) (retry 1/100)
D (18886) usb_terminal: 0x3fcb8240   0d 0a 53 4d 53 20 52 65  61 64 79 0d 0a           |..SMS Ready..|
D (19136) command_lib: generic_get_string
D (19136) command_lib: generic_get_string
D (19136) usb_terminal: 0x3fcc726c   41 54 2b 43 47 4d 49 0d                           |AT+CGMI.|
D (19136) usb_terminal: 0x3fcb824d   41 54 2b 43 47 4d 49 0d                           |AT+CGMI.|
D (19146) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 4c 74 64 0d 0a 0d 0a  |..SIMCOM_Ltd....|
D (19156) usb_terminal: 0x3fcb823c   4f 4b 0d 0a                                       |OK..|
} (19166) command_lib: Token: {

D (19166) command_lib: Token: {SIMCOM_Ltd}

} (19176) command_lib: Token: {

D (19176) command_lib: Token: {OK}

I (19186) gsm_modem: GSM manufacturer: [SIMCOM_Ltd]
D (19216) command_lib: generic_get_string
D (19216) command_lib: generic_get_string
D (19216) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (19226) usb_terminal: 0x3fcb822c   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (19226) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (19236) usb_terminal: 0x3fcb823c   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
D (19236) gsm_modem: Cmd result: ERROR (1) (retry 1/10)
D (19756) command_lib: generic_get_string
D (19756) command_lib: generic_get_string
D (19756) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (19776) usb_terminal: 0x3fcb8244   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (19776) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (19786) usb_terminal: 0x3fcb823c   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
D (19786) gsm_modem: Cmd result: ERROR (1) (retry 2/10)
D (20296) command_lib: generic_get_string
D (20296) command_lib: generic_get_string
D (20296) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (20306) usb_terminal: 0x3fcb8244   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (20316) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (20316) usb_terminal: 0x3fcb823c   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
D (20316) gsm_modem: Cmd result: ERROR (1) (retry 3/10)
D (20836) command_lib: generic_get_string
D (20836) command_lib: generic_get_string
D (20836) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (20846) usb_terminal: 0x3fcb8244   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (20846) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (20856) usb_terminal: 0x3fcb823c   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
D (20856) gsm_modem: Cmd result: ERROR (1) (retry 4/10)
D (21386) command_lib: generic_get_string
D (21386) command_lib: generic_get_string
D (21386) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (21406) usb_terminal: 0x3fcb8244   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (21406) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (21406) usb_terminal: 0x3fcb823c   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
D (21416) gsm_modem: Cmd result: ERROR (1) (retry 5/10)
D (21926) command_lib: generic_get_string
D (21926) command_lib: generic_get_string
D (21926) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (21946) usb_terminal: 0x3fcb8244   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (21946) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (21946) usb_terminal: 0x3fcb823c   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
D (21956) gsm_modem: Cmd result: ERROR (1) (retry 6/10)
I (22156) ocpp_protocol: Sending Heartbeat.req
D (22476) command_lib: generic_get_string
D (22476) command_lib: generic_get_string
D (22476) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (22496) usb_terminal: 0x3fcb8244   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (22496) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (22506) usb_terminal: 0x3fcb823c   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
D (22506) gsm_modem: Cmd result: ERROR (1) (retry 7/10)
D (23036) command_lib: generic_get_string
D (23036) command_lib: generic_get_string
D (23036) usb_terminal: 0x3fcc72ac   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (23036) usb_terminal: 0x3fcb8244   41 54 2b 43 47 4d 4d 0d                           |AT+CGMM.|
D (23046) usb_terminal: 0x3fcb822c   0d 0a 53 49 4d 43 4f 4d  5f 53 49 4d 37 30 37 30  |..SIMCOM_SIM7070|
D (23056) usb_terminal: 0x3fcb823c   0d 0a 0d 0a 4f 4b 0d 0a                           |....OK..|
} (23066) command_lib: Token: {

D (23066) command_lib: Token: {SIMCOM_SIM7070}

} (23076) command_lib: Token: {

D (23076) command_lib: Token: {OK}

I (23086) gsm_modem: GSM HW model: [SIMCOM_SIM7070]

The SimCom SIM7070G is connected via USB. The component configuration for esp_modem is default (CONFIG_ESP_MODEM_USE_INFLATABLE_BUFFER_IF_NEEDED not set). I don't use CMUX (it was completely broken over USB, but that's another story altogether).

My debugger indicates that we never get around to parsing the modem response with generic_get_string. Instead this line activates, indicating a buffer over/underflow issue. In the same time I've configured the DTE with a buffer of 1536 bytes, so there's something else going on here. https://github.com/espressif/esp-protocols/blob/2e6732882d813f7830fdc0604da49221b91a134d/components/esp_modem/src/esp_modem_dte.cpp#L114C30-L114C30

[david-cermak]

Sorry for the regression. It's just been fixed on master in https://github.com/espressif/esp-protocols/commit/1db1e1508d63c9d03161e3b7785f6cc7a2ac81b8

I'll merge few minor fixes and create v1.0.4 soon (also added a USB runner to our CI to prevent it from happening in future)

[DaStoned]

Ah, thank you. That's good news!

[DaStoned]

I tried with 1.0.4 and cannot reproduce the regression. So I confirm the fix. Thank you.