esp32 s3 fails to connect to mqtt ssl broker with A7670C lte modem (IDFGH-12966)

[VaishnaviSPadiyappanavar]

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

ESP32 S3 is connected to the A7670C lte modem via usb and the pppos_client is being used from esp_modem external component . ESP32 S3 succesfully connects to the Non-SSL broker but fails to connect to the SSL Mqtt broker

these are logs when it fails to connect to mqtt broker I (7263) APP_MQTT: Client started I (7263) HEAP_CHECK: Free heap size DURING MQTT SSL CONNECTION: 214548 bytes I (7273) APP_MQTT: Waiting for bits I (7793) mbedtls: ssl_tls.c:3939 => handshake

I (7803) mbedtls: ssl_msg.c:2124 => flush output

I (7803) mbedtls: ssl_msg.c:2133 <= flush output

I (7803) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_HELLO_REQUEST

I (7813) mbedtls: ssl_msg.c:2124 => flush output

I (7813) mbedtls: ssl_msg.c:2133 <= flush output

I (7823) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_CLIENT_HELLO

I (7833) mbedtls: ssl_client.c:906 => write client hello

W (7833) mbedtls: ssl_client.c:258 got supported group(001d)

W (7843) mbedtls: ssl_client.c:258 got supported group(0017)

W (7853) mbedtls: ssl_client.c:258 got supported group(0018)

W (7853) mbedtls: ssl_client.c:258 got supported group(0019)

W (7863) mbedtls: ssl_client.c:258 got supported group(001a)

W (7863) mbedtls: ssl_client.c:258 got supported group(001b)

W (7873) mbedtls: ssl_client.c:258 got supported group(001c)

I (7883) mbedtls: ssl_msg.c:2554 => write handshake message

I (7883) mbedtls: ssl_msg.c:2714 => write record

I (7893) mbedtls: ssl_msg.c:2851 <= write record

I (7903) mbedtls: ssl_msg.c:2675 <= write handshake message

I (7903) mbedtls: ssl_client.c:994 <= write client hello

I (7913) mbedtls: ssl_msg.c:2124 => flush output

I (7913) mbedtls: ssl_msg.c:2138 message length: 246, out_left: 246

I (7923) mbedtls: ssl_msg.c:2145 ssl->f_send() returned 246 (-0xffffff0a)

I (7933) mbedtls: ssl_msg.c:2172 <= flush output

I (7933) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_SERVER_HELLO

I (7943) mbedtls: ssl_tls12_client.c:1195 => parse server hello

I (7953) mbedtls: ssl_msg.c:3887 => read record

I (7953) mbedtls: ssl_msg.c:1926 => fetch input

I (7963) mbedtls: ssl_msg.c:2066 in_left: 0, nb_want: 5

I (8263) mbedtls: ssl_msg.c:2086 in_left: 0, nb_want: 5

I (8263) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (8263) mbedtls: ssl_msg.c:2111 <= fetch input

I (8273) mbedtls: ssl_msg.c:1926 => fetch input

I (8273) mbedtls: ssl_msg.c:2066 in_left: 5, nb_want: 70

I (8283) mbedtls: ssl_msg.c:2086 in_left: 5, nb_want: 70

I (8293) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 65 (-0xffffffbf)

I (8303) mbedtls: ssl_msg.c:2111 <= fetch input

I (8303) mbedtls: ssl_msg.c:3959 <= read record

I (8313) mbedtls: ssl_tls12_client.c:1446 server hello, total extension length: 21

I (8313) mbedtls: ssl_tls12_client.c:1660 <= parse server hello

I (8323) mbedtls: ssl_msg.c:2124 => flush output

I (8333) mbedtls: ssl_msg.c:2133 <= flush output

I (8333) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_SERVER_CERTIFICATE

I (8343) mbedtls: ssl_tls.c:7559 => parse certificate

I (8353) mbedtls: ssl_msg.c:3887 => read record

I (8353) mbedtls: ssl_msg.c:1926 => fetch input

I (8363) mbedtls: ssl_msg.c:2066 in_left: 0, nb_want: 5

I (8363) mbedtls: ssl_msg.c:2086 in_left: 0, nb_want: 5

I (8373) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (8383) mbedtls: ssl_msg.c:2111 <= fetch input

I (8383) mbedtls: ssl_msg.c:1926 => fetch input

I (8393) mbedtls: ssl_msg.c:2066 in_left: 5, nb_want: 2082

I (8393) mbedtls: ssl_msg.c:2086 in_left: 5, nb_want: 2082

I (8403) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 2077 (-0xfffff7e3)

I (8413) mbedtls: ssl_msg.c:2111 <= fetch input

I (8433) mbedtls: ssl_msg.c:3959 <= read record

I (8463) mbedtls: ssl_tls.c:7672 <= parse certificate

I (8463) mbedtls: ssl_msg.c:2124 => flush output

I (8463) mbedtls: ssl_msg.c:2133 <= flush output

I (8463) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_SERVER_KEY_EXCHANGE

I (8473) mbedtls: ssl_tls12_client.c:2082 => parse server key exchange

I (8483) mbedtls: ssl_msg.c:3887 => read record

I (8483) mbedtls: ssl_msg.c:1926 => fetch input

I (8493) mbedtls: ssl_msg.c:2066 in_left: 0, nb_want: 5

I (8493) mbedtls: ssl_msg.c:2086 in_left: 0, nb_want: 5

I (8503) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (8513) mbedtls: ssl_msg.c:2111 <= fetch input

I (8513) mbedtls: ssl_msg.c:1926 => fetch input

I (8523) mbedtls: ssl_msg.c:2066 in_left: 5, nb_want: 305

I (8533) mbedtls: ssl_msg.c:2086 in_left: 5, nb_want: 305

I (8533) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 300 (-0xfffffed4)

I (8543) mbedtls: ssl_msg.c:2111 <= fetch input

I (8553) mbedtls: ssl_msg.c:3959 <= read record

I (8553) mbedtls: ssl_tls12_client.c:1805 ECDH curve: x25519

I (8583) mbedtls: ssl_tls12_client.c:2452 <= parse server key exchange

I (8583) mbedtls: ssl_msg.c:2124 => flush output

I (8583) mbedtls: ssl_msg.c:2133 <= flush output

I (8593) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_CERTIFICATE_REQUEST

I (8593) mbedtls: ssl_tls12_client.c:2491 => parse certificate request

I (8603) mbedtls: ssl_msg.c:3887 => read record

I (8613) mbedtls: ssl_msg.c:1926 => fetch input

I (8613) mbedtls: ssl_msg.c:2066 in_left: 0, nb_want: 5

I (8623) mbedtls: ssl_msg.c:2086 in_left: 0, nb_want: 5

I (8633) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (8633) mbedtls: ssl_msg.c:2111 <= fetch input

I (8643) mbedtls: ssl_msg.c:1926 => fetch input

I (8643) mbedtls: ssl_msg.c:2066 in_left: 5, nb_want: 57

I (8653) mbedtls: ssl_msg.c:2086 in_left: 5, nb_want: 57

I (8663) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 52 (-0xffffffcc)

I (8663) mbedtls: ssl_msg.c:2111 <= fetch input

I (8673) mbedtls: ssl_msg.c:3959 <= read record

I (8683) mbedtls: ssl_tls12_client.c:2655 <= parse certificate request

I (8683) mbedtls: ssl_msg.c:2124 => flush output

I (8693) mbedtls: ssl_msg.c:2133 <= flush output

I (8693) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_SERVER_HELLO_DONE

I (8703) mbedtls: ssl_tls12_client.c:2666 => parse server hello done

I (8713) mbedtls: ssl_msg.c:3887 => read record

I (8713) mbedtls: ssl_msg.c:1926 => fetch input

I (8723) mbedtls: ssl_msg.c:2066 in_left: 0, nb_want: 5

I (8733) mbedtls: ssl_msg.c:2086 in_left: 0, nb_want: 5

I (8733) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

I (8743) mbedtls: ssl_msg.c:2111 <= fetch input

I (8753) mbedtls: ssl_msg.c:1926 => fetch input

I (8753) mbedtls: ssl_msg.c:2066 in_left: 5, nb_want: 9

I (8763) mbedtls: ssl_msg.c:2086 in_left: 5, nb_want: 9

I (8763) mbedtls: ssl_msg.c:2089 ssl->f_recv(_timeout)() returned 4 (-0xfffffffc)

I (8773) mbedtls: ssl_msg.c:2111 <= fetch input

I (8783) mbedtls: ssl_msg.c:3959 <= read record

I (8783) mbedtls: ssl_tls12_client.c:2694 <= parse server hello done

I (8793) mbedtls: ssl_msg.c:2124 => flush output

I (8803) mbedtls: ssl_msg.c:2133 <= flush output

I (8803) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_CLIENT_CERTIFICATE

I (8813) mbedtls: ssl_tls.c:6963 => write certificate

I (8823) mbedtls: ssl_msg.c:2554 => write handshake message

I (8823) mbedtls: ssl_msg.c:2714 => write record

I (8833) mbedtls: ssl_msg.c:2124 => flush output

I (8833) mbedtls: ssl_msg.c:2138 message length: 1004, out_left: 1004

I (8843) mbedtls: ssl_msg.c:2145 ssl->f_send() returned 1004 (-0xfffffc14)

I (8853) mbedtls: ssl_msg.c:2172 <= flush output

I (8853) mbedtls: ssl_msg.c:2851 <= write record

I (8863) mbedtls: ssl_msg.c:2675 <= write handshake message

I (8863) mbedtls: ssl_tls.c:7036 <= write certificate

I (8873) mbedtls: ssl_msg.c:2124 => flush output

I (8883) mbedtls: ssl_msg.c:2133 <= flush output

I (8883) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_CLIENT_KEY_EXCHANGE

I (8893) mbedtls: ssl_tls12_client.c:2709 => write client key exchange

I (9163) mbedtls: ssl_msg.c:2554 => write handshake message

I (9163) mbedtls: ssl_msg.c:2714 => write record

I (9163) mbedtls: ssl_msg.c:2124 => flush output

I (9163) mbedtls: ssl_msg.c:2138 message length: 42, out_left: 42

I (9173) mbedtls: ssl_msg.c:2145 ssl->f_send() returned 42 (-0xffffffd6)

I (9183) mbedtls: ssl_msg.c:2172 <= flush output

I (9183) mbedtls: ssl_msg.c:2851 <= write record

I (9193) mbedtls: ssl_msg.c:2675 <= write handshake message

I (9193) mbedtls: ssl_tls12_client.c:3203 <= write client key exchange

I (9203) mbedtls: ssl_msg.c:2124 => flush output

I (9213) mbedtls: ssl_msg.c:2133 <= flush output

I (9213) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_CERTIFICATE_VERIFY

I (9223) mbedtls: ssl_tls12_client.c:3251 => write certificate verify

I (9233) mbedtls: ssl_tls.c:6555 => derive keys

I (9233) mbedtls: ssl_tls.c:6730 => calc verify sha384

I (9243) mbedtls: ssl_tls.c:6749 <= calc verify

I (9253) mbedtls: ssl_tls.c:6606 <= derive keys

I (9253) mbedtls: ssl_tls.c:6730 => calc verify sha384

I (9263) mbedtls: ssl_tls.c:6749 <= calc verify

I (9833) mbedtls: ssl_msg.c:2554 => write handshake message

I (9833) mbedtls: ssl_msg.c:2714 => write record

I (9833) mbedtls: ssl_msg.c:2124 => flush output

I (9833) mbedtls: ssl_msg.c:2138 message length: 269, out_left: 269

I (9843) mbedtls: ssl_msg.c:2145 ssl->f_send() returned 269 (-0xfffffef3)

I (9853) mbedtls: ssl_msg.c:2172 <= flush output

I (9853) mbedtls: ssl_msg.c:2851 <= write record

I (9863) mbedtls: ssl_msg.c:2675 <= write handshake message

I (9873) mbedtls: ssl_tls12_client.c:3363 <= write certificate verify

I (9873) mbedtls: ssl_msg.c:2124 => flush output

I (9883) mbedtls: ssl_msg.c:2133 <= flush output

I (9883) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_CLIENT_CHANGE_CIPHER_SPEC

I (9893) mbedtls: ssl_msg.c:4889 => write change cipher spec

I (9903) mbedtls: ssl_msg.c:2554 => write handshake message

I (9913) mbedtls: ssl_msg.c:2714 => write record

I (9913) mbedtls: ssl_msg.c:2124 => flush output

I (9923) mbedtls: ssl_msg.c:2138 message length: 6, out_left: 6

I (9923) mbedtls: ssl_msg.c:2145 ssl->f_send() returned 6 (-0xfffffffa)

I (9933) mbedtls: ssl_msg.c:2172 <= flush output

I (9943) mbedtls: ssl_msg.c:2851 <= write record

I (9943) mbedtls: ssl_msg.c:2675 <= write handshake message

I (9953) mbedtls: ssl_msg.c:4902 <= write change cipher spec

I (9953) mbedtls: ssl_msg.c:2124 => flush output

I (9963) mbedtls: ssl_msg.c:2133 <= flush output

I (9973) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_CLIENT_FINISHED

I (9973) mbedtls: ssl_tls.c:7963 => write finished

I (9983) mbedtls: ssl_tls.c:7829 => calc finished tls sha384

I (9993) mbedtls: ssl_tls.c:7861 <= calc finished

I (9993) mbedtls: ssl_msg.c:2554 => write handshake message

I (10003) mbedtls: ssl_msg.c:2714 => write record

I (10003) mbedtls: ssl_msg.c:715 => encrypt buf

I (10013) mbedtls: ssl_msg.c:1256 <= encrypt buf

I (10013) mbedtls: ssl_msg.c:2124 => flush output

I (10023) mbedtls: ssl_msg.c:2138 message length: 45, out_left: 45

I (10033) mbedtls: ssl_msg.c:2145 ssl->f_send() returned 45 (-0xffffffd3)

I (10033) mbedtls: ssl_msg.c:2172 <= flush output

I (10043) mbedtls: ssl_msg.c:2851 <= write record

I (10053) mbedtls: ssl_msg.c:2675 <= write handshake message

I (10053) mbedtls: ssl_tls.c:8065 <= write finished

I (10063) mbedtls: ssl_msg.c:2124 => flush output

I (10063) mbedtls: ssl_msg.c:2133 <= flush output

I (10073) mbedtls: ssl_tls.c:3859 client state: MBEDTLS_SSL_SERVER_CHANGE_CIPHER_SPEC

I (10083) mbedtls: ssl_tls12_client.c:3379 => parse new session ticket

I (10083) mbedtls: ssl_msg.c:3887 => read record

I (10093) mbedtls: ssl_msg.c:1926 => fetch input

I (10103) mbedtls: ssl_msg.c:2066 in_left: 0, nb_want: 5

I (20103) mbedtls: ssl_msg.c:2086 in_left: 0, nb_want: 5

I (20103) mbedtls: ssl_tls.c:3950 <= handshake

W (20103) esp-tls: Failed to open new connection in specified timeout E (20103) transport_base: Failed to open a new connection E (20113) mqtt_client: Error transport connect I (20113) APP_MQTT: INFO:MQTT EVENT_0 E (20123) APP_MQTT: INFO:MQTT_EVENT_ERROR I (20123) APP_MQTT: INFO:MQTT EVENT_2 I (20133) APP_MQTT: INFO:Client disconnected

[david-cermak]

W (20103) esp-tls: Failed to open new connection in specified timeout

looks like the SSL handshake just didn't complete in the specified network timeout, have you tried to increase it? (you can directly update it in the mqtt config structure)

[VaishnaviSPadiyappanavar]

yes we have increased the timeout till 60 seconds but still the issue is not solved with this.

[VaishnaviSPadiyappanavar]

Just a quick follow-up on my previous message . I'm still facing the same issue and would greatly appreciate any suggestions you might have. Do you think the issue could be related to USB?.

[david-cermak]

I wasn't able to reproduce the issue, just checked with SIMCOM A7670 over USB and this public broker mqtts://mqtt.eclipseprojects.io:8883 and everything works as expected.

Are you able to connect to your broker using WiFi or Ethernet? Could you check with some public service, so I'd be able to replicate the problem?

[VaishnaviSPadiyappanavar]

Yes, we can connect to our MQTT SSL broker via WiFi and Ethernet. We also connected to the public broker mqtts://mqtt.eclipseprojects.io:8883 without issues. However, our MQTT SSL broker requires certificates for validation, and it isn't working in that case

[david-cermak]

I was able to reproduce the issue when trying to connect to another public service mqtts://test.mosquitto.org:8884 which requires client side verification.

The issue seems to be related to the USB host transmit size. At the moment I can offer the following workaround:

diff --git a/components/esp_modem/src/esp_modem_netif.cpp b/components/esp_modem/src/esp_modem_netif.cpp
index d808db07..5a550d52 100644
--- a/components/esp_modem/src/esp_modem_netif.cpp
+++ b/components/esp_modem/src/esp_modem_netif.cpp
@@ -32,9 +32,23 @@ esp_err_t Netif::esp_modem_dte_transmit(void *h, void *buffer, size_t len)
 {
     auto *ppp = static_cast<Netif *>(h);
     if (ppp->signal.is_any(PPP_STARTED)) {
-        if (ppp->ppp_dte && ppp->ppp_dte->write((uint8_t *) buffer, len) > 0) {
-            return ESP_OK;
+        ESP_LOGD("Modem Netif", "Tx size(%d)", len);
+        if (!ppp->ppp_dte) {
+            return ESP_FAIL;
         }
+
+        uint8_t *ptr = (uint8_t*)buffer;
+        const size_t max_len = 256;
+        size_t remain = len;
+        while (remain > 0) {
+            int batch = std::min(max_len, remain);
+            if (ppp->ppp_dte->write(ptr, batch) <= 0) {
+                return ESP_FAIL;
+            }
+            remain -= batch;
+            ptr += batch;
+        }
+        return ESP_OK;
     }
     return ESP_FAIL;
 }
@@ -65,6 +79,7 @@ esp_err_t Netif::esp_modem_post_attach(esp_netif_t *esp_netif, void *args)

 void Netif::receive(uint8_t *data, size_t len)
 {
+    ESP_LOGD("Modem Netif", "Rx size(%d)", len);
     esp_netif_receive(driver.base.netif, data, len, nullptr);
 }

Thanks for reporting! We'll look into it and fix it.

[VaishnaviSPadiyappanavar]

@david-cermak Thank you for the workaround!. Just to confirm, do you foresee any potential issues or drawbacks with this workaround in the long run?

[david-cermak]

Yes, it's safe to patch the modem layer as noted above, or better yet in the https://github.com/david-cermak/esp-protocols/commit/09252003c3af1dbd4d8be8c4800aee7718fe2798 (which uses configured DTE buffer size, rather than the hardcoded value).

Of course, it is not recommended to use any unofficial or unreleased versions of any library, long term, so I'd suggest:

• increase the DTE buffer to 2048 (enough for the MTU of PPP layer which is 1500 by default) -- that should fix the problem and you could use the latest released version of esp-modem
• wait for the fix to be deployed. I'd preferably fix it directly in the esp-usb rather than accepting https://github.com/espressif/esp-protocols/pull/593, but this won't happen earlier than next week. I assume the fixed version should be available by the end of next week.