MQTT SSL Muthual auth. cannot connect (IDFGH-3409)

Nomuc commented 4 years ago

Environment

Development Kit: [ESP32-DevKitC]
Kit version (DevKitC): [v3]
Module or chip used: [ESP32-WROOM-32D]
IDF version : v3.3
Build System: [idf.py]
Compiler version: v2.50200.80
Operating System: [Windows]
(Windows only) environment type: [PowerShell].
Using an IDE?: [Yes (PlatformIO)]
Power Supply: [USB]

Problem

Hello,

I got to create a project using MQTT with SSL Muthual auth., so I used the example project from ESP-IDF, it is going perfectly everytime I try to connect to my broker with ECDSA key type and SHA-256.

Then I try to run it on my project with the same sample code to connect and I got a mbed_ssl handshake problem (-0x7280) everytime :

esp-tls : mbed_ssl_handshake returned -0x7280 esp-tls : Certificate verified. esp-tls : Failed to open a new connection. TRANS_SSL : Failed to open a new connection. MQTT_CLIENT : Error transport connect.

I have checked the error by it means nothing to me, it is called CONN_EOF error.

I added debug log level 4 on TLS and I found this :

(17213) mbedtls: components\mbedtls\mbedtls\library\ssl_tls.c:2779 ssl->f_send() returned -80 (-0x0050)

(17228) mbedtls: components\mbedtls\mbedtls\library\ssl_tls.c:3472 mbedtls_ssl_flush_output() returned -80 (-0x0050)

(17245) mbedtls: components\mbedtls\mbedtls\library\ssl_tls.c:3315 ssl_write_record() returned -80 (-0x0050)

(17262) mbedtls: components\mbedtls\mbedtls\library\ssl_cli.c:3379 mbedtls_ssl_write_handshake_msg() returned -80 (-0x0050)

(17280) mbedtls: components\mbedtls\mbedtls\library\ssl_tls.c:8096 <= handshake

(17294) esp-tls: mbedtls_ssl_handshake returned -0x50 (17299) esp-tls: Certificate verified. (17308) esp-tls: Failed to open new connection (17309) TRANS_SSL: Failed to open a new connection (17315) MQTT_CLIENT: Error transport connect

Everytime ssl->f_send is returning -0x0050 or -0x7280 and I do not understand why.

I have copied paste the sdkconfig files into my working project and then it works 2 times out of 10.

Alvin1Zhang commented 4 years ago

Thanks for reporting, we will look into. @david-cermak

david-cermak commented 4 years ago

Hi @Nomuc

It seems like the server actively closes the connection during handshake (MBEDTLS_ERR_SSL_CONN_EOF simply says the connection is closed, so what I think is happening is that the client side tries to write -- continue with the handshake -- but the socket is already closed from the other side, so network write returns -0x50 and the handshake then terminates CONN_EOF)

Are you able to retrieve some logs from the broker? This info should indicate why the connection was closed as apparently from client side the termination of the connection looks unexpected. The other option would be to check the packet capture in wireshark to see which phase of the handshake caused issues (should be visible from mbedtls logs, as well, but would need complete log file).

I have copied paste the sdkconfig files into my working project and then it works 2 times out of 10.

This is strange, as the mqtt mutual authentication example doesn't define any specific configs, just goes with defaults (maybe if you switch between different IDF versions, there might be some differences, but typically just buffer sizes, etc)... Is it possible to diff the previous sdkconfig just to see where the difference lies?

Nomuc commented 4 years ago

Hello @david-cermak,

When you say the server is closing before the end of the handshake it is weird because I can connect with the same cert on the mqtt example, I also tried to connect to my broker with mosquitto and it did works.

The logs of debug from the broker are empty, only refreshing ticks...

Find the mbedtls logs below :

(6981) MQTT: Before connect event n:7 (7236) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:8086 => handshake

(7240) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 0

(7254) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(7268) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(7282) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 1

(7297) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(7311) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(7325) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:774 => write client hello

(7345) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3184 => write handshake message

(7357) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3343 => write record

(7374) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(7383) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2774 message length: 220, out_left: 220

(7402) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2779 ssl->f_send() returned 220 (-0xffffff24)

(7416) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2807 <= flush output

(7430) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3476 <= write record

(7444) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3320 <= write handshake message

(7459) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:1106 <= write client hello

(7474) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 2

(7488) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(7503) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(7517) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:1499 => parse server hello

(7532) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4311 => read record

(7546) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(7560) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 0, nb_want: 5

(7575) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 0, nb_want: 5

(7590) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

(7607) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(7622) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(7635) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 5, nb_want: 92

(7650) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 5, nb_want: 92

(7665) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 87 (-0xffffffa9)

(7682) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(7701) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4385 <= read record

(7713) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:1789 server hello, total extension length: 11

(7727) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:1978 <= parse server hello

(7741) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 3

(7756) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(7770) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(7784) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:5655 => parse certificate

(7799) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4311 => read record

(7813) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(7827) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 0, nb_want: 5

(7842) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 0, nb_want: 5

(7857) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

(7874) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(7888) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(7902) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 5, nb_want: 993

(7917) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 5, nb_want: 993

(7932) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 988 (-0xfffffc24)

(7950) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(7983) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4385 <= read record

(9854) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:5863 <= parse certificate

(9858) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 4

(9872) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(9887) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(9901) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2336 => parse server key exchange

(9916) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4311 => read record

(9930) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(9945) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 0, nb_want: 5

(9960) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 0, nb_want: 5

(9974) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

(9991) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(10006) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(10020) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 5, nb_want: 220

(10035) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 5, nb_want: 220

(10050) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 215 (-0xffffff29)

(10067) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(10086) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4385 <= read record

(10100) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2044 ECDH curve: secp521r1

(10113) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2278 Server used SignatureAlgorithm 3

(10126) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2279 Server used HashAlgorithm 6

(11980) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2664 <= parse server key exchange

(11985) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 5

(11999) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(12013) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(12028) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2697 => parse certificate request

(12043) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4311 => read record

(12058) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(12072) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 0, nb_want: 5

(12087) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 0, nb_want: 5

(12102) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

(12119) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(12134) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(12147) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 5, nb_want: 291

(12164) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 5, nb_want: 291

(12178) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 286 (-0xfffffee2)

(12195) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(12215) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4385 <= read record

(12224) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2846 <= parse certificate request

(12239) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 6

(12253) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(12267) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(12282) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2856 => parse server hello done

(12297) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4311 => read record

(12311) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(12325) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 0, nb_want: 5

(12342) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 0, nb_want: 5

(12356) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

(12373) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(12387) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2536 => fetch input

(12401) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2697 in_left: 5, nb_want: 9

(12416) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2721 in_left: 5, nb_want: 9

(12431) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2722 ssl->f_recv(_timeout)() returned 4 (-0xfffffffc)

(12448) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2742 <= fetch input

(12463) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:4385 <= read record

(12477) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2886 <= parse server hello done

(12492) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 7

(12506) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(12520) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(12535) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:5329 => write certificate

(12553) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3184 => write handshake message

(12566) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3343 => write record

(12588) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(12593) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2774 message length: 500, out_left: 500

(12611) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2779 ssl->f_send() returned 500 (-0xfffffe0c)

(12626) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2807 <= flush output

(12640) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3476 <= write record

(12655) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3320 <= write handshake message

(12670) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:5433 <= write certificate

(12685) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3510 client state: 8

(12699) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(12713) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2767 <= flush output

(12728) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:2898 => write client key exchange

(16283) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3184 => write handshake message

(16289) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3343 => write record

(16305) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2755 => flush output

(16317) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2774 message length: 143, out_left: 143

(16333) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:2779 ssl->f_send() returned -80 (-0x0050)

(16349) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3472 mbedtls_ssl_flush_output() returned -80 (-0x0050)

(16366) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:3315 ssl_write_record() returned -80 (-0x0050)

(16383) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_cli.c:3168 mbedtls_ssl_write_handshake_msg() returned -80 (-0x0050)

(16400) mbedtls: C:\Users\abu.platformio\packages\framework-espidf@3.30300.190916\components\mbedtls\mbedtls\library\ssl_tls.c:8096 <= handshake

(16414) esp-tls: mbedtls_ssl_handshake returned -0x50 (16420) esp-tls: Certificate verified. (16429) esp-tls: Failed to open new connection (16430) TRANS_SSL: Failed to open a new connection (16436) MQTT_CLIENT: Error transport connect

I also got the difference between the 2 sdkconfig files but nothing feels related to MQTT, find it below :

Define in addition from my project :

CONFIG_ESPTOOLPY_BAUD, CONFIG_ESPTOOLPY_BAUD_115200B, CONFIG_PYTHON, CONFIG_ESP32_TIME_SYSCALL_USE_RTC_FRC1, CONFIG_ESPTOOLPY_COMPRESSED, CONFIG_PARTITION_TABLE_SINGLE_APP, CONFIG_ADC_CAL_EFUSE_TP_ENABLE, CONFIG_ADC_CAL_EFUSE_VREF_ENABLE, CONFIG_ESPTOOLPY_PORT

Define in addition coming from mqtt mutual auth example :

CONFIG_IDF_CMAKE, CONFIG_IDF_FIRMWARE_CHIP_ID, CONFIG_PARTITION_TABLE_CUSTOM, CONFIG_BTDM_CTRL_BR_EDR_SCO_DATA_PATH_EFF, CONFIG_BTDM_CONTROLLER_MODEM_SLEEP, CONFIG_BTDM_MODEM_SLEEP_MODE_ORIG, CONFIG_BTDM_LPCLK_SEL_MAIN_XTAL, CONFIG_ESP32_TIME_SYSCALL_USE_RTC, CONFIG_ESP32_DPORT_DIS_INTERRUPT_LVL, CONFIG_EMAC_L2_TO_L3_RX_BUF_MODE, CONFIG_LWIP_SNTP_UPDATE_DELAY,

PS : I just tried again with new certificates on esp32 mqtt mutual auth test project, I got a -0x50 error.

david-cermak commented 4 years ago

@Nomuc Thanks for sharing the logs!

When you say the server is closing before the end

What I meant was (an assumption) that the server closed the connection, because it didn't like "something" within the handshake, and to find out what that something was, we could check the server log or the packet capture.

From what I can see from your log, it fails in the state nr. 8, which is MBEDTLS_SSL_CLIENT_KEY_EXCHANGE, which is just after the MBEDTLS_SSL_CLIENT_CERTIFICATE so we could assume that this something is somewhere close to the client certificate.

The logs of debug from the broker are empty, only refreshing ticks...

What kind of broker you use? It is mosquitto? It should be possible to make the logging more verbose, at least to see the incoming TCP connection.

but nothing feels related to MQTT,

This issue is not related to MQTT, as the tls handshake fails before it gets to employ the MQTT library at all, but TBH I don't see any related config options to mbedTLS, nor networking. So I think that was just a coincidence that the connection went from none to intermittent after the config update.

Nomuc commented 4 years ago

Thanks for your help @david-cermak

As broker we use VerneMQ ( https://docs.vernemq.com/configuration/logging ), even in debug mode there are no interesting logs ...

I told me the same but that was the only interesting way I had.

Nomuc commented 4 years ago

We are connecting with mosquitto in this following way : mosquitto_sub -h <dns> -p <port> --cafile CA.crt -t "<topic>" -q 0 -i <clientid> -P <password> -u <username> -d --cert Middle/devices/PRIME256/cert.crt --key Middle/devices/PRIME256/key.pem --insecure --insecure is used because the broker cert CN is not the actual broker DNS, so we had to add this code :

We instantly return before check CN to avoid problems.

Can this cause unwanted side effects ?

Edit : I tried with a broker certificate where CN is OK and without the return but I got the same error on f_rcv(_timeout).

almini commented 4 years ago

We have the same problem and also use a VerneMQ broker but without a client certificate. Could you somehow resolve the issue?

Nomuc commented 4 years ago

Hi @almini ,

I managed to solve the problem recently, the problem for me was the clock frequency.

I used to be at 80MHz, I saw that going to 160MHz allowed me to connect to the broker. I did some tests (shutting down WiFi) and at 160MHz the product couldn't reconnect to the broker, but at 240MHz it is working everytime at the first try. I think VerneMQ is sending an EOF after 5 seconds of connection try, and ESP32 is too slow under 240MHz ...

@david-cermak any updates on this ?

david-cermak commented 4 years ago

@Nomuc Thanks for sharing your update and sorry for not responding. As mentioned in my initial post the server seemed to close the connection due to some server side timeout.

I'm sorry I really wasn't able to see the root cause from the logs nor from the symptoms described here. Moreover I'm not familiar with VerneMQ broker and its config options (I should have asked for the packet capture in the first place to clearly see the connection gets really closed from the server side)

As for the CN check, that should not cause any related issue (and in case of problems we would see the relevant mbedtls logs). Please note that you can achieve the same without modification of mbedtls sources, please see how the skip_common_name option is used in esp-tls component here https://github.com/espressif/esp-idf/blob/master/components/esp-tls/esp_tls_mbedtls.c#L383 (if you use mbedtls API directly or just set this to true if using esp-tls API)

almini commented 4 years ago

@Nomuc Thanks for the hint. In newer versions of VerneMQ it is possible to configure the timeout (https://github.com/vernemq/vernemq/pull/1527). Increasing the timeout solved our issues.

Nomuc commented 4 years ago

Thanks for your answer @almini, I will also try that on my side.

I will close the issue since the problem is solved for both of us.

espressif / esp-idf

MQTT SSL Muthual auth. cannot connect (IDFGH-3409) #5374

Environment

Problem