franz-ms-muc
commented
2 years ago Sorry, Logfile coming soon.
Closed franz-ms-muc closed 2 years ago
franz-ms-muc
commented
2 years ago Sorry, Logfile coming soon.
VasilNikolovRilabs
commented
2 years ago @franz-ms-muc What we have observed is the following error: ESP_ERR_MBEDTLS_SSL_HANDSHAKE_FAILED. The same issue with the same certificates and private keys does not happen when connecting to the back end with WiFi STA. Issue is almost always observed when using ESP MODEM with SIM7070
E (24105) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x7280
I (24115) esp-tls-mbedtls: Certificate verified.
E (24115) esp-tls: Failed to open new connection```@franz-ms-muc Another information: it seems that HTTPS is possible over ESP MODEM with SIM7070 but not MQTTS. The problem is only happening when starting the MQTTS connection to the server, OTA via HTTPS is working fine(with the same certificates)
david-cermak
commented
2 years ago The reported error of 0x7280 means:
The connection indicated an EOF.
So it looks like the MQTT broker closed the connection before the handshake completed. The reason why it works over WiFi might be that the server would validate some timeout and the connection is simply faster over WiFi.
VasilNikolovRilabs
commented
2 years ago @david-cermak Thank for your feedback, do you have any hint for us which setting on the server side can influence the timing behavior of the TLS?
franz-ms-muc
commented
2 years ago 
VasilNikolovRilabs
commented
2 years ago @david-cermak @franz-ms-muc
I am attaching the traces of the TLS handshake with extended trace output for TLS and TCP.
In the first trace "wifi_log_netif&tls.txt" we clearly see that TLS is working using the same server and same certificates. `I (42425) mbedtls: ssl_msg.c:2346 <= write handshake message
I (42435) mbedtls: ssl_tls.c:2867 <= write finished
I (42445) mbedtls: ssl_msg.c:1789 => flush output
I (42445) mbedtls: ssl_msg.c:1801 <= flush output
I (42455) mbedtls: ssl_cli.c:4192 client state: 12
I (42455) mbedtls: ssl_cli.c:4077 => parse new session ticket
I (42465) mbedtls: ssl_msg.c:3546 => read record
I (42465) mbedtls: ssl_msg.c:1573 => fetch input
I (42475) mbedtls: ssl_msg.c:1730 in_left: 0, nb_want: 5
I (42475) mbedtls: ssl_msg.c:1755 in_left: 0, nb_want: 5
I (42485) mbedtls: ssl_msg.c:1756 ssl->f_recv(_timeout)() returned 0 (-0x0000)
W (42495) mbedtls: ssl_msg.c:4228 mbedtls_ssl_fetch_input() returned -29312 (-0x7280)
W (42505) mbedtls: ssl_msg.c:3579 ssl_get_next_record() returned -29312 (-0x7280)
W (42505) mbedtls: ssl_cli.c:4081 mbedtls_ssl_read_record() returned -29312 (-0x7280)
I (42515) mbedtls: ssl_tls.c:5323 <= handshake`
In the second trace "simcom_log_netif&tls.txt" the TLS session is started correctly: `I (49576) mbedtls: ssl_msg.c:2346 <= write handshake message
I (49586) mbedtls: ssl_tls.c:2867 <= write finished
I (49596) mbedtls: ssl_msg.c:1789 => flush output
I (49596) mbedtls: ssl_msg.c:1801 <= flush output
I (49606) mbedtls: ssl_cli.c:4192 client state: 12
I (49606) mbedtls: ssl_cli.c:4077 => parse new session ticket
I (49616) mbedtls: ssl_msg.c:3546 => read record
I (49616) mbedtls: ssl_msg.c:1573 => fetch input
I (49626) mbedtls: ssl_msg.c:1730 in_left: 0, nb_want: 5
tcp_slowtmr: processing active pcb tcp_recved: received 5 bytes, wnd 4652 (1092). I (50166) mbedtls: ssl_msg.c:1755 in_left: 0, nb_want: 5
I (50166) mbedtls: ssl_msg.c:1756 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)
I (50166) mbedtls: ssl_msg.c:1776 <= fetch input
I (50176) mbedtls: ssl_msg.c:1573 => fetch input
I (50176) mbedtls: ssl_msg.c:1730 in_left: 5, nb_want: 1046 `
MartinPatarinski
commented
2 years ago @david-cermak @franz-ms-muc After further investigation and enabling logging of lwip we were able to get more information of the root cause. During the TLS handshake procedure we receive a "Connection closed" error: lwip_recv_tcp: p == NULL, error is "Connection closed."! Whenever we retry a couple of times, the connection is established successfully and MQTT runs normally. Here is the log of a connection failed and after that connection OK attempts:
I (41180) BE_CommManager: MQTT_EVENT_BEFORE_CONNECT lwip_socket(PF_INET, SOCK_STREAM, 0) = 54 lwip_connect(54, addr=85.236.61.186 port=9883) lwip_connect(54) failed, err=-5 lwip_select(55, 0x0, 0x3fcc17e4, 0x0, tvsec=10 tvusec=0) lwip_selscan: fd=54 ready for writing lwip_select: nready=1 lwip_getsockopt(54, SOL_SOCKET, SO_ERROR) = 0 lwip_send(54, data=0x3fcc8158, size=251, flags=0x0) lwip_send(54) err=0 written=251 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc9898 lwip_recv_tcp: buflen=1280 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 87, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=1275 recv_left=87 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=87 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=1188 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 1939, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=1183 recv_left=1939 off=0 lwip_recv_tcp: deleting pbuf=0x3fcc9898 lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=-7, pbuf=0x0 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=1183 lwip_recvfrom(54, 0x3fcc44a8, 756, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc9898 lwip_recv_tcp: buflen=1280 recv_left=756 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=756 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=524 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 333, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=519 recv_left=333 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=333 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=186 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 176, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=181 recv_left=176 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=176 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=5 recv_left=5 off=0 lwip_recv_tcp: deleting pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 4, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fccbc1c lwip_recv_tcp: buflen=4 recv_left=4 off=0 lwip_recv_tcp: deleting pbuf=0x3fccbc1c lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=4 lwip_send(54, data=0x3fcc8158, size=914, flags=0x0) lwip_send(54) err=0 written=914 lwip_send(54, data=0x3fcc8158, size=75, flags=0x0) lwip_send(54) err=0 written=75 lwip_send(54, data=0x3fcc8158, size=269, flags=0x0) lwip_send(54) err=0 written=269 lwip_send(54, data=0x3fcc8158, size=6, flags=0x0) lwip_send(54) err=0 written=6 lwip_send(54, data=0x3fcc8158, size=45, flags=0x0) lwip_send(54) err=0 written=45 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=-15, pbuf=0x0 lwip_recv_tcp: p == NULL, error is "Connection closed."! lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=0 E (47230) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x7280 I (47230) esp-tls-mbedtls: Certificate verified. E (47240) esp-tls: Failed to open new connection E (47240) TRANSPORT_BASE: Failed to open a new connection lwip_shutdown(54, how=2) lwip_close(54) E (47250) mqtt_client: Error transport connect E (47260) BE_CommManager: MQTT_EVENT_ERROR E (47260) BE_CommManager: Last error code reported from esp-tls: 0x801a: ESP_ERR_MBEDTLS_SSL_HANDSHAKE_FAILED E (47270) BE_CommManager: Last tls stack error number: 0x7280: ERROR E (47280) BE_CommManager: Last captured errno : 0 (Success) I (47290) BE_CommManager: MQTT_EVENT_DISCONNECTED I (51180) mqtt_client: Client force reconnect requested I (51180) BE_CommManager: MQTT_EVENT_BEFORE_CONNECT lwip_socket(PF_INET, SOCK_STREAM, 0) = 54 lwip_connect(54, addr=85.236.61.186 port=9883) lwip_connect(54) failed, err=-5 lwip_select(55, 0x0, 0x3fcc17e4, 0x0, tvsec=10 tvusec=0) lwip_selscan: fd=54 ready for writing lwip_select: nready=1 lwip_getsockopt(54, SOL_SOCKET, SO_ERROR) = 0 lwip_send(54, data=0x3fcc8158, size=251, flags=0x0) lwip_send(54) err=0 written=251 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc9898 lwip_recv_tcp: buflen=1280 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 87, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=1275 recv_left=87 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=87 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=1188 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 1939, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=1183 recv_left=1939 off=0 lwip_recv_tcp: deleting pbuf=0x3fcc9898 lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=-7, pbuf=0x0 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=1183 lwip_recvfrom(54, 0x3fcc44a8, 756, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc9898 lwip_recv_tcp: buflen=1280 recv_left=756 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=756 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=524 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 333, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=519 recv_left=333 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=333 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=186 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 176, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=181 recv_left=176 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=176 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fcc9898 lwip_recv_tcp: buflen=5 recv_left=5 off=0 lwip_recv_tcp: deleting pbuf=0x3fcc9898 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 4, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fccb72c lwip_recv_tcp: buflen=4 recv_left=4 off=0 lwip_recv_tcp: deleting pbuf=0x3fccb72c lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=4 lwip_send(54, data=0x3fcc8158, size=914, flags=0x0) lwip_send(54) err=0 written=914 lwip_send(54, data=0x3fcc8158, size=75, flags=0x0) lwip_send(54) err=0 written=75 lwip_send(54, data=0x3fcc8158, size=269, flags=0x0) lwip_send(54) err=0 written=269 lwip_send(54, data=0x3fcc8158, size=6, flags=0x0) lwip_send(54) err=0 written=6 lwip_send(54, data=0x3fcc8158, size=45, flags=0x0) lwip_send(54) err=0 written=45 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fccbed4 lwip_recv_tcp: buflen=51 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fccbed4 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 1, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fccbed4 lwip_recv_tcp: buflen=46 recv_left=1 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fccbed4 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=1 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fccbed4 lwip_recv_tcp: buflen=45 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fccbed4 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 40, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fccbed4 lwip_recv_tcp: buflen=40 recv_left=40 off=0 lwip_recv_tcp: deleting pbuf=0x3fccbed4 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=40 lwip_select(55, 0x0, 0x3fcc17d8, 0x3fcc17e0, tvsec=10 tvusec=0) lwip_selscan: fd=54 ready for writing lwip_select: nready=1 lwip_send(54, data=0x3fcc8158, size=55, flags=0x0) lwip_send(54) err=0 written=55 lwip_select(55, 0x3fcc1798, 0x0, 0x3fcc17a0, tvsec=10 tvusec=0) lwip_selscan: fd=54 ready for reading lwip_select: nready=1 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fccad80 lwip_recv_tcp: buflen=33 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fccad80 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 28, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fccad80 lwip_recv_tcp: buflen=28 recv_left=28 off=0 lwip_recv_tcp: deleting pbuf=0x3fccad80 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=28 I (58530) BE_CommManager: MQTT_EVENT_CONNECTED lwip_select(55, 0x3fcc1868, 0x0, 0x3fcc1870, tvsec=1 tvusec=0) lwip_select: timeout expired lwip_select(55, 0x3fcc1798, 0x0, 0x3fcc17a0, tvsec=0 tvusec=0) lwip_select: no timeout, returning 0 lwip_select(55, 0x3fcc1868, 0x0, 0x3fcc1870, tvsec=1 tvusec=0) lwip_select: timeout expired lwip_select(55, 0x3fcc1798, 0x0, 0x3fcc17a0, tvsec=0 tvusec=0) lwip_select: no timeout, returning 0 lwip_select(55, 0x3fcc1868, 0x0, 0x3fcc1870, tvsec=1 tvusec=0) lwip_select(55, 0x0, 0x3fcabce8, 0x3fcabcf0, tvsec=10 tvusec=0) lwip_selscan: fd=54 ready for writing lwip_select: nready=1 lwip_send(54, data=0x3fcc8158, size=125, flags=0x0) lwip_send(54) err=0 written=125 lwip_select: timeout expired lwip_select(55, 0x3fcc1798, 0x0, 0x3fcc17a0, tvsec=0 tvusec=0) lwip_select: no timeout, returning 0 lwip_select(55, 0x0, 0x3fcc17a8, 0x3fcc17b0, tvsec=10 tvusec=0) lwip_selscan: fd=54 ready for writing lwip_select: nready=1 lwip_send(54, data=0x3fcc8158, size=31, flags=0x0) lwip_send(54) err=0 written=31 lwip_select(55, 0x3fcc1868, 0x0, 0x3fcc1870, tvsec=1 tvusec=0) lwip_selscan: fd=54 ready for reading lwip_select: nready=1 lwip_select(55, 0x3fcc1798, 0x0, 0x3fcc17a0, tvsec=0 tvusec=0) lwip_selscan: fd=54 ready for reading lwip_select: nready=1 lwip_recvfrom(54, 0x3fcc4004, 5, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x0 lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fccc910 lwip_recv_tcp: buflen=34 recv_left=5 off=0 lwip_recv_tcp: lastdata now pbuf=0x3fccc910 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=5 lwip_recvfrom(54, 0x3fcc4009, 29, 0x0, ..) lwip_recv_tcp: top while sock->lastdata=0x3fccc910 lwip_recv_tcp: buflen=29 recv_left=29 off=0 lwip_recv_tcp: deleting pbuf=0x3fccc910 lwip_recvfrom(54): addr=85.236.61.186 port=9883 len=29 I (62220) BE_CommManager: MQTT_EVENT_SUBSCRIBED, msg_id=19949 lwip_select(55, 0x3fcc1868, 0x0, 0x3fcc1870, tvsec=1 tvusec=0) lwip_selscan: fd=54 ready for reading
david-cermak
commented
2 years ago As said above. The connection gets closed actively from the server, (socket operation returning 0 is EOF, as mentioned in the initial error message and my comment), so there's not much we could do on the client's end.
Unfortunately I'm not familiar with server settings, I usually run a local mosquitto which AFAIK doesn't have such config.
I think we couldn't address this on client's end, unless we silently retry, or speed up the connection somehow? (like increasing the CPU frequency or updating the baudrate if your board can handle it or perhaps using USB instead of UART?)
MartinPatarinski
commented
2 years ago Thank you , David! We managed to setup a local Mosquitto with TLS and the ESP32 device works with it via Modem internet connection. The "connection closed" is not observed. We can close this issue.
david-cermak
commented
2 years ago Thanks for the info, closing
There is an error observed in the ESP log when using the Modem for connection to the Backend server.
The error is sporadic.
Logfile: