search

espressif / esp-mqtt

ESP32 mqtt component
Apache License 2.0
610 stars 257 forks source link

SLL connection takes a lot of attempt before success up to 8minutes (ssl handshake err -0x7280) #98

Closed AloyseTech closed 4 years ago

AloyseTech commented 5 years ago

Hi,

I use the ssl with autheticatin example as a base for my firmware. BLE is continuously scanning for devices and report some of them over mqtt. I have to wait almost 10 minutes to have a succesfull MQTT connection. I repeatedly get the following error : I (516750) MQTT: Other event id:7 E (517280) esp-tls: mbedtls_ssl_handshake returned -0x7280 E (517280) esp-tls: Failed to open new connection E (517280) TRANS_SSL: Failed to open a new connection E (517290) MQTT_CLIENT: Error transport connect W (517290) MQTT: MQTT_EVENT_DISCONNECTED

After around 10 minutes the connection is successful. But if it disconnect, there the same delay again.

david-cermak commented 5 years ago

Can you somehow reduce the functionality (BLE + other) to only the ssl connection and check if the issue persists?

The error 0x7280 means that the broker actively terminated connection, one cause might be a "very long" initial ssl handshake (which seeing from the log would not be your case as it fails within 1s) One way to debug the issue is to enable mbedtls debugging in menuconfig (components->mbedtls->enable debugging) and check which phase of ssl handshake returns error/warnings.

AloyseTech commented 5 years ago

Hi David,

I've disabled the BLE part of my application and the issue persists. Here is the log of the first attempt with mbedTLS debug enabled : 

D (2766) MQTT_CLIENT: MQTT client_id=ESP32_698204
D (2776) MQTT_CLIENT: Core selection disabled
I (2776) MQTT: Other event id:7
D (2776) esp-tls: host:test.mosquitto.org: strlen 18
D (3346) esp-tls: handshake in progress...
I (3346) mbedtls: ssl_tls.c:8021 => handshake
I (3346) mbedtls: ssl_cli.c:3405 client state: 0
I (3346) mbedtls: ssl_tls.c:2751 => flush output
I (3356) mbedtls: ssl_tls.c:2763 <= flush output
I (3356) mbedtls: ssl_cli.c:3405 client state: 1
I (3366) mbedtls: ssl_tls.c:2751 => flush output
I (3376) mbedtls: ssl_tls.c:2763 <= flush output
I (3376) mbedtls: ssl_cli.c:774 => write client hello
D (3386) mbedtls: ssl_cli.c:812 client hello, max version: [3:3]
D (3386) mbedtls: ssl_cli.c:703 client hello, current time: 3
D (3396) mbedtls: ssl_cli.c:821 dumping 'client hello, random bytes' (32 bytes)
D (3406) mbedtls: ssl_cli.c:821 0000:  00 00 00 03 88 16 52 90 04 38 d8 b1 79 30 e0 64
......R..8..y0.d
D (3416) mbedtls: ssl_cli.c:821 0010:  7c cb db b1 4a 74 2c 80 7e 08 d6 62 f8 fb fa 1d
|...Jt,.~..b....
D (3426) mbedtls: ssl_cli.c:874 client hello, session id len.: 0
D (3426) mbedtls: ssl_cli.c:875 dumping 'client hello, session id' (0 bytes)
D (3436) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c02c
D (3446) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c030
D (3446) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 009f
D (3456) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c0ad
D (3466) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c09f
D (3466) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c024
D (3476) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c028
D (3486) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 006b
D (3486) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c00a
D (3496) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c014
D (3506) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 0039
D (3506) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c0af
D (3516) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c0a3
D (3516) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c02b
D (3526) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c02f
D (3536) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 009e
D (3536) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c0ac
D (3546) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c09e
D (3556) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c023
D (3556) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c027
D (3566) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 0067
D (3576) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c009
D (3576) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c013
D (3586) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 0033
D (3596) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c0ae
D (3596) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c0a2
D (3606) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 009d
D (3616) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c09d
D (3616) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 003d
D (3626) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 0035
D (3636) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c032
D (3636) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c02a
D (3646) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c00f
D (3646) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c02e
D (3656) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c026
D (3666) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c005
D (3666) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c0a1
D (3676) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 009c
D (3686) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c09c
D (3686) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 003c
D (3696) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: 002f
D (3706) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c031
D (3706) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c029
D (3716) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c00e
D (3726) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c02d
D (3726) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c025
D (3736) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c004
D (3746) mbedtls: ssl_cli.c:922 client hello, add ciphersuite: c0a0
D (3746) mbedtls: ssl_cli.c:934 client hello, got 48 ciphersuites (excluding SCSVs)
D (3756) mbedtls: ssl_cli.c:943 adding EMPTY_RENEGOTIATION_INFO_SCSV
D (3766) mbedtls: ssl_cli.c:992 client hello, compress len.: 1
D (3766) mbedtls: ssl_cli.c:994 client hello, compress alg.: 0
D (3776) mbedtls: ssl_cli.c:69 client hello, adding server name extension: test.mosquitt
o.org
D (3786) mbedtls: ssl_cli.c:186 client hello, adding signature_algorithms extension
D (3796) mbedtls: ssl_cli.c:271 client hello, adding supported_elliptic_curves extension

D (3796) mbedtls: ssl_cli.c:336 client hello, adding supported_point_formats extension
D (3806) mbedtls: ssl_cli.c:518 client hello, adding encrypt_then_mac extension
D (3816) mbedtls: ssl_cli.c:552 client hello, adding extended_master_secret extension
D (3826) mbedtls: ssl_cli.c:585 client hello, adding session ticket extension
D (3836) mbedtls: ssl_cli.c:1071 client hello, total extension length: 99
I (3836) mbedtls: ssl_tls.c:3180 => write handshake message
I (3846) mbedtls: ssl_tls.c:3337 => write record
D (3846) mbedtls: ssl_tls.c:3417 output record: msgtype = 22, version = [3:1], msglen =
242
V (3856) mbedtls: ssl_tls.c:3420 dumping 'output record sent to network' (247 bytes)
V (3866) mbedtls: ssl_tls.c:3420 0000:  16 03 01 00 f2 01 00 00 ee 03 03 00 00 00 03 88
 ................
V (3876) mbedtls: ssl_tls.c:3420 0010:  16 52 90 04 38 d8 b1 79 30 e0 64 7c cb db b1 4a
 .R..8..y0.d|...J
V (3886) mbedtls: ssl_tls.c:3420 0020:  74 2c 80 7e 08 d6 62 f8 fb fa 1d 00 00 62 c0 2c
 t,.~..b......b.,
V (3896) mbedtls: ssl_tls.c:3420 0030:  c0 30 00 9f c0 ad c0 9f c0 24 c0 28 00 6b c0 0a
 .0.......$.(.k..
V (3906) mbedtls: ssl_tls.c:3420 0040:  c0 14 00 39 c0 af c0 a3 c0 2b c0 2f 00 9e c0 ac
 ...9.....+./....
V (3916) mbedtls: ssl_tls.c:3420 0050:  c0 9e c0 23 c0 27 00 67 c0 09 c0 13 00 33 c0 ae
 ...#.'.g.....3..
V (3926) mbedtls: ssl_tls.c:3420 0060:  c0 a2 00 9d c0 9d 00 3d 00 35 c0 32 c0 2a c0 0f
 .......=.5.2.*..
V (3936) mbedtls: ssl_tls.c:3420 0070:  c0 2e c0 26 c0 05 c0 a1 00 9c c0 9c 00 3c 00 2f
 ...&.........<./
V (3946) mbedtls: ssl_tls.c:3420 0080:  c0 31 c0 29 c0 0e c0 2d c0 25 c0 04 c0 a0 00 ff
 .1.)...-.%......
V (3956) mbedtls: ssl_tls.c:3420 0090:  01 00 00 63 00 00 00 17 00 15 00 00 12 74 65 73
 ...c.........tes
V (3966) mbedtls: ssl_tls.c:3420 00a0:  74 2e 6d 6f 73 71 75 69 74 74 6f 2e 6f 72 67 00  t.mosquitto.org.
V (3976) mbedtls: ssl_tls.c:3420 00b0:  0d 00 16 00 14 06 03 06 01 05 03 05 01 04 03 04  ................
V (3986) mbedtls: ssl_tls.c:3420 00c0:  01 03 03 03 01 02 03 02 01 00 0a 00 18 00 16 00  ................
V (3996) mbedtls: ssl_tls.c:3420 00d0:  19 00 1c 00 18 00 1b 00 17 00 16 00 1a 00 15 00  ................
V (4006) mbedtls: ssl_tls.c:3420 00e0:  14 00 13 00 12 00 0b 00 02 01 00 00 16 00 00 00  ................
V (4016) mbedtls: ssl_tls.c:3420 00f0:  17 00 00 00 23 00 00                             ....#..
I (4026) mbedtls: ssl_tls.c:2751 => flush output
I (4026) mbedtls: ssl_tls.c:2770 message length: 247, out_left: 247
I (4036) mbedtls: ssl_tls.c:2775 ssl->f_send() returned 247 (-0xffffff09)
I (4046) mbedtls: ssl_tls.c:2803 <= flush output
I (4046) mbedtls: ssl_tls.c:3470 <= write record
I (4056) mbedtls: ssl_tls.c:3314 <= write handshake message
I (4056) mbedtls: ssl_cli.c:1106 <= write client hello
I (4066) mbedtls: ssl_cli.c:3405 client state: 2
I (4076) mbedtls: ssl_tls.c:2751 => flush output
I (4076) mbedtls: ssl_tls.c:2763 <= flush output
I (4086) mbedtls: ssl_cli.c:1499 => parse server hello
I (4086) mbedtls: ssl_tls.c:4305 => read record
I (4096) mbedtls: ssl_tls.c:2532 => fetch input
I (4096) mbedtls: ssl_tls.c:2693 in_left: 0, nb_want: 5
I (4106) mbedtls: ssl_tls.c:2717 in_left: 0, nb_want: 5
I (4116) mbedtls: ssl_tls.c:2718 ssl->f_recv(_timeout)() returned 0 (-0x0000)
W (4116) mbedtls: ssl_tls.c:4967 mbedtls_ssl_fetch_input() returned -29312 (-0x7280)
W (4126) mbedtls: ssl_tls.c:4338 ssl_get_next_record() returned -29312 (-0x7280)
W (4136) mbedtls: ssl_cli.c:1506 mbedtls_ssl_read_record() returned -29312 (-0x7280)
I (4146) mbedtls: ssl_tls.c:8031 <= handshake
E (4146) esp-tls: mbedtls_ssl_handshake returned -0x7280
E (4156) esp-tls: Failed to open new connection
E (4166) TRANS_SSL: Failed to open a new connection
E (4166) MQTT_CLIENT: Error transport connect
D (4176) MQTT_CLIENT: Reconnect after 10000 ms
W (4176) MQTT: MQTT_EVENT_DISCONNECTED
david-cermak commented 5 years ago

Hi @AloyseTech

Thanks for sharing the details. I can see the error occurs directly after the client hello and I can reproduce it locally to see the server sends RST after receiving client_hello. My suspicion is that there's something wrong is test.mosquitto.org (they're actually saying to run unreleased/experimental code). Also checked that I'm not able to connect to it with a python script:

ssl.SSLEOFError: EOF occurred in violation of protocol (_ssl.c:726)

Nor with mosquitto's pub/sub tools: Error: The connection was lost.

Also I do remember the same code did work with test.mosquitto.org some time ago (as mentioned here https://github.com/espressif/esp-idf/issues/2993 while having some cert issues).

Have you tried to use any other server? Like iot.eclipse.org or locally installed mosquitto?

AloyseTech commented 5 years ago

Hi David, Sorry I missed the notification. I will test this with another server and let you know.

david-cermak commented 5 years ago

Hi @AloyseTech

Any news? Have you had a chance to test it with another server or local installation?

AloyseTech commented 4 years ago

Hi @david-cermak , I'm sorry for the very late reply. This issue has not be solved back in the days : in the rush we switched to AWS. I can't reproduce it now with ESP-IDF 4.0-beta2.