ESPAsyncTCP icon indicating copy to clipboard operation
ESPAsyncTCP copied to clipboard

Correct ssl recv

Open mhightower83 opened this issue 5 years ago • 16 comments

Corrected missed edit for _recv() in ASYNC_TCP_SSL_ENABLED in AsyncServer::_poll(). And other missed edit for errorTracker around ASYNC_TCP_SSL_ENABLED. This should resolve @kasedy comment https://github.com/me-no-dev/ESPAsyncTCP/pull/115#issuecomment-538816623 and @mcspr.

Tested ASYNC_TCP_SSL_ENABLED using marvinroger/async-mqtt-client/ ... examples/FullyFeaturedSSL. Ran test against test.mosquitto.org's server. Thanks to @mcspr for suggesting.

Updated tcp_ssl_read() to check for fd_data being freed by callback functions. I observed this with asyncmqttclient example. When fingerprint did not match during fd_data->on_handshake callback, the MQTT library did a close(true) which rippled down to a tcp_ssl_free().

Improvements in debug printing to handle debug print from tcp.axtls.c.

mhightower83 avatar Oct 10 '19 05:10 mhightower83

I tested this code, it compiles but doesn't seem to work with https://github.com/marvinroger/async-mqtt-client.

I get the following logging: 000003.975 [TCP_SSL] tcp_ssl_new: 0 000003.986 [ASYNC_TCP] _recv[1]: 536 000003.986 [TCP_SSL] tcp_ssl_ssl_read: 0 000003.994 [TCP_SSL] tcp_ssl_ssl_read: 0 000003.998 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.001 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.007 [ASYNC_TCP] _recv[1]: 536 000004.008 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.015 [ASYNC_TCP] _recv[1]: 536 000004.016 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.023 [ASYNC_TCP] _recv[1]: 536 000004.024 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.031 [ASYNC_TCP] _recv[1]: 536 000004.032 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.039 [ASYNC_TCP] _recv[1]: 138 000004.067 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.071 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.257 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.268 [ASYNC_TCP] _recv[1]: 91 000004.269 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.277 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.281 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.286 [TCP_SSL] tcp_ssl_ssl_read: 0 000004.290 [TCP_SSL] tcp_ssl_read: handshake OK 000004.353 [ASYNC_TCP] _sent[1]: 536, unacked= 462, acked= 536, space= 482 000004.365 [ASYNC_TCP] _sent[1]: 462, unacked= 0, acked= 998, space= 944 000034.321 [ASYNC_TCP] _poll[1]: SSL Handshake Timeout. 000034.321 [TCP_SSL] tcp_ssl_free: 0 000034.334 [ASYNC_TCP] _close[1]: AsyncClient 0x3FFF18A4

On the mqtt server I can see this in the log: 1572546996: New connection from 192.168.2.145 on port 8883. 1572547001: Client has exceeded timeout, disconnecting.

When not using SSL it just works fine...

What can this be?

jeroenst avatar Oct 31 '19 18:10 jeroenst

This is the result I get going to "test.mosquitto.org" Note the send at 000003.221 is much smaller in my log than yours. I really don't know much about SSL. I'll have to look later at what is being sent. The send precedes the Connected to MQTT so I assume we are still in the SSL setup stage.

Connecting to Wi-Fi...
Connected to Wi-Fi.
Connecting to MQTT...
000002.328 [TCP_SSL] tcp_ssl_new: 0
000002.514 [ASYNC_TCP] _recv[1]: 536
000002.514 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.522 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.525 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.529 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.534 [ASYNC_TCP] _recv[1]: 536
000002.534 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.541 [ASYNC_TCP] _recv[1]: 536
000002.541 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.549 [ASYNC_TCP] _recv[1]: 414
000002.568 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.571 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.758 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.976 [ASYNC_TCP] _recv[1]: 91
000002.977 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.985 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.988 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.993 [TCP_SSL] tcp_ssl_ssl_read: 0
000002.997 [TCP_SSL] tcp_ssl_read: handshake OK
000003.221 [ASYNC_TCP] _sent[1]:  536, unacked=  16, acked= 536, space= 928  <<<< This is curious, this is where our logs differ.
000003.380 [ASYNC_TCP] _sent[1]:   16, unacked=   0, acked= 552, space= 944
000003.386 [ASYNC_TCP] _recv[1]: 69
000003.387 [TCP_SSL] tcp_ssl_ssl_read: 0
000003.396 [TCP_SSL] tcp_ssl_ssl_read: 4
Connected to MQTT.
Session present: 0
Subscribing at QoS 2, packetId: 1
Publishing at QoS 0
Publishing at QoS 1, packetId: 2
Publishing at QoS 2, packetId: 0
000003.576 [ASYNC_TCP] _sent[1]:  536, unacked= 430, acked= 536, space= 514
000003.577 [ASYNC_TCP] _recv[1]: 69
000003.577 [TCP_SSL] tcp_ssl_ssl_read: 0
000003.592 [TCP_SSL] tcp_ssl_ssl_read: 5
Subscribe acknowledged.
  packetId: 1
  qos: 2
000003.597 [ASYNC_TCP] _recv[1]: 85
000003.597 [TCP_SSL] tcp_ssl_ssl_read: 0
000003.608 [TCP_SSL] tcp_ssl_ssl_read: 20
Publish received.
  topic: test/lol
  qos: 1
  dup: 0
  retain: 1
  len: 6
  index: 0
  total: 6
000003.755 [ASYNC_TCP] _sent[1]:  430, unacked=   0, acked= 966, space= 944
000003.756 [ASYNC_TCP] _recv[1]: 85
000003.756 [TCP_SSL] tcp_ssl_ssl_read: 0
000003.770 [TCP_SSL] tcp_ssl_ssl_read: 18
Publish received.
  topic: test/lol
  qos: 0
  dup: 0
  retain: 0
  len: 6
  index: 0
  total: 6
000003.776 [ASYNC_TCP] _recv[1]: 69
000003.776 [TCP_SSL] tcp_ssl_ssl_read: 0
000003.791 [TCP_SSL] tcp_ssl_ssl_read: 4
Publish acknowledged.
  packetId: 2
000003.797 [ASYNC_TCP] _recv[1]: 85
000003.797 [TCP_SSL] tcp_ssl_ssl_read: 0
000003.807 [TCP_SSL] tcp_ssl_ssl_read: 20
Publish received.
  topic: test/lol
  qos: 1
  dup: 0
  retain: 0
  len: 6
  index: 0
  total: 6
000004.261 [ASYNC_TCP] _sent[1]:   69, unacked=  69, acked=  69, space= 875
000004.429 [ASYNC_TCP] _sent[1]:   69, unacked=   0, acked= 138, space= 944
000004.741 [ASYNC_TCP] _sent[1]:   69, unacked=  69, acked=  69, space= 875
000004.902 [ASYNC_TCP] _sent[1]:   69, unacked=   0, acked= 138, space= 944
000014.903 [ASYNC_TCP] _sent[1]:   69, unacked=   0, acked=  69, space= 944
000014.904 [ASYNC_TCP] _recv[1]: 69
000014.905 [TCP_SSL] tcp_ssl_ssl_read: 0
000014.919 [TCP_SSL] tcp_ssl_ssl_read: 2
000025.442 [ASYNC_TCP] _sent[1]:   69, unacked=   0, acked=  69, space= 944
000025.443 [ASYNC_TCP] _recv[1]: 69
000025.443 [TCP_SSL] tcp_ssl_ssl_read: 0
000025.457 [TCP_SSL] tcp_ssl_ssl_read: 2
000036.100 [ASYNC_TCP] _sent[1]:   69, unacked=   0, acked=  69, space= 944
000036.101 [ASYNC_TCP] _recv[1]: 69
000036.101 [TCP_SSL] tcp_ssl_ssl_read: 0
000036.116 [TCP_SSL] tcp_ssl_ssl_read: 2

mhightower83 avatar Oct 31 '19 20:10 mhightower83

Maybe it's because of different option configured (I use setwill for example). Still strange, because in your logging you get response from the MQTT server while in my example, no response is received. I will try without setwill.

jeroenst avatar Nov 01 '19 13:11 jeroenst

Ok, your code is working.

I bumped into this bug: https://github.com/marvinroger/async-mqtt-client/issues/107

jeroenst avatar Nov 01 '19 13:11 jeroenst

I solved the bug in async-mqtt-client.

MQTT with SSL with your code works fine now.

jeroenst avatar Nov 01 '19 16:11 jeroenst

The best way to solve this completely imo is to change the code, create a addtobuffer and a sendbuffer function and send 1 packet instead of multiple in all current functions.

But I don't have time at the moment to do this.

jeroenst avatar Nov 01 '19 16:11 jeroenst

I ran into issues when compiling an esphome project depending on ESPAsyncTCP with SSL enabled. This PR solved the issues. Thanks! (Thanks as well for the hint on the MQTT bug, I ran into it as well..., but again your PR in the other repo fixes it)

moritzj29 avatar Nov 02 '19 19:11 moritzj29

@me-no-dev ESPAsyncTCP latest doesn't compile with SSL enabled. Can you please merge this pull request so SSL compiles again? I can confirm it works.

jeroenst avatar Dec 14 '19 09:12 jeroenst

I have the same compilation problems and ESPAsyncTCP works with this pull request with SSL without any problems yet. I would appreciate a merge, too.

kleini avatar Dec 14 '19 12:12 kleini

@mhightower83 it would be good, to rebase your fix on the master branch instead of merging the master branch into your branch.

kleini avatar Dec 31 '19 13:12 kleini

@me-no-dev ESPAsyncTCP latest doesn't compile with SSL enabled. Can you please merge this pull request so SSL compiles again? I can confirm it works.

jeroenst avatar Apr 23 '21 06:04 jeroenst

how can I dowonload this pull request? @jeroenst

miloit avatar Jul 27 '21 18:07 miloit

how can I dowonload this pull request? @jeroenst

I believe I did this :

Git fetch Git checkout 4e39b7ff6e85cab643fc548edc16661da738a055

Otherwise get asynctcp from my github repo.

jeroenst avatar Jul 27 '21 22:07 jeroenst

how can I dowonload this pull request? @jeroenst

With PlatformIO you can do in platformio.ini:

lib_deps =
  https://github.com/mhightower83/ESPAsyncTCP#correct-ssl-_recv

kleini avatar Jul 28 '21 06:07 kleini

how can I dowonload this pull request? @jeroenst

I believe I did this :

Git fetch Git checkout 4e39b7f

Otherwise get asynctcp from my github repo.

Hey jeroenst. Could you please elaborate how did you manage to get this working: -what ESP SDK have you used, -if and what flags/particular settings or other info required to get this specific version of espasynctcp working on esp8266. Thanks !

gecoool avatar Jan 23 '22 20:01 gecoool

@gecoool I use arduino ide with esp8266 board version 2.7.4

jeroenst avatar Jan 24 '22 07:01 jeroenst