ssl handshake takes too much time

[LupascuAndrei]

Sometimes, the ssl handshake takes too much time using micropython on esp32:

def wlan_connect(ssid='MYSSID', password='MYPASS'):
    import network
    wlan = network.WLAN(network.STA_IF)
    if not wlan.active() or not wlan.isconnected():
        wlan.active(True)
        print('connecting to:', ssid)
        wlan.connect(ssid, password)
        while not wlan.isconnected():
            pass
    print('network config:', wlan.ifconfig())
wlan_connect(ssid='ssid', password='pass')

import utime 
for i in range(1000):
  print('sleeping 2s')
  utime.sleep(2)
  try:
      import usocket as _socket
  except:
      import _socket
  try:
      import ussl as ssl
  except:
      import ssl
  s = _socket.socket()

  s.connect((IP,PORT))

  import utime
  delta = utime.ticks_ms();
  s = ssl.wrap_socket(s)
  delta = utime.ticks_ms() - delta; 
  print('time spent on handshake : ' + str( delta/1000) + ' seconds ; handshake no. = ' + str(i))
  s.close()

Using the above code, logs look something like this:

(...)
time spent on handshake : 1.22 seconds ; handshake no. = 29
time spent on handshake : 1.277 seconds ; handshake no. = 30
time spent on handshake : 1.249 seconds ; handshake no. = 31
time spent on handshake : 1.181 seconds ; handshake no. = 32
time spent on handshake : 1.18 seconds ; handshake no. = 33
time spent on handshake : 1.64 seconds ; handshake no. = 35
time spent on handshake : 3.414 seconds ; handshake no. = 36
time spent on handshake : 1.197 seconds ; handshake no. = 37
time spent on handshake : 1.201 seconds ; handshake no. = 38
time spent on handshake : 1.219 seconds ; handshake no. = 39
time spent on handshake : 1.206 seconds ; handshake no. = 40
time spent on handshake : 2.987 seconds ; handshake no. = 41
time spent on handshake : 1.206 seconds ; handshake no. = 42
time spent on handshake : 1.167 seconds ; handshake no. = 44
time spent on handshake : 1.188 seconds ; handshake no. = 46
time spent on handshake : 1.177 seconds ; handshake no. = 47
time spent on handshake : 1.41 seconds ; handshake no. = 48
time spent on handshake : 1.156 seconds ; handshake no. = 49
time spent on handshake : 1.166 seconds ; handshake no. = 50
time spent on handshake : 1.184 seconds ; handshake no. = 51
time spent on handshake : 1.145 seconds ; handshake no. = 52
time spent on handshake : 1.218 seconds ; handshake no. = 53
time spent on handshake : 1.434 seconds ; handshake no. = 54
time spent on handshake : 1.339 seconds ; handshake no. = 55
time spent on handshake : 1.19 seconds ; handshake no. = 56
time spent on handshake : 1.195 seconds ; handshake no. = 57
time spent on handshake : 3.239 seconds ; handshake no. = 58
time spent on handshake : 1.256 seconds ; handshake no. = 59
time spent on handshake : 1.286 seconds ; handshake no. = 60
time spent on handshake : 1.284 seconds ; handshake no. = 61
time spent on handshake : 1.281 seconds ; handshake no. = 62
time spent on handshake : 1.504 seconds ; handshake no. = 63
time spent on handshake : 1.222 seconds ; handshake no. = 64
time spent on handshake : 1.183 seconds ; handshake no. = 65
time spent on handshake : 1.554 seconds ; handshake no. = 66
time spent on handshake : 1.273 seconds ; handshake no. = 67
time spent on handshake : 2.46 seconds ; handshake no. = 68
time spent on handshake : 1.398 seconds ; handshake no. = 70
time spent on handshake : 1.255 seconds ; handshake no. = 71
time spent on handshake : 1.382 seconds ; handshake no. = 72
time spent on handshake : 1.448 seconds ; handshake no. = 73
time spent on handshake : 21.411 seconds ; handshake no. = 74        ( <- here )       
time spent on handshake : 1.432 seconds ; handshake no. = 75
time spent on handshake : 1.364 seconds ; handshake no. = 76
time spent on handshake : 1.307 seconds ; handshake no. = 77
time spent on handshake : 1.738 seconds ; handshake no. = 78
time spent on handshake : 1.276 seconds ; handshake no. = 79
time spent on handshake : 1.751 seconds ; handshake no. = 80
time spent on handshake : 2.945 seconds ; handshake no. = 81
time spent on handshake : 1.237 seconds ; handshake no. = 82
time spent on handshake : 1.287 seconds ; handshake no. = 83
time spent on handshake : 1.199 seconds ; handshake no. = 84
time spent on handshake : 1.148 seconds ; handshake no. = 85
time spent on handshake : 1.264 seconds ; handshake no. = 87
time spent on handshake : 1.196 seconds ; handshake no. = 88
time spent on handshake : 1.249 seconds ; handshake no. = 89
time spent on handshake : 1.173 seconds ; handshake no. = 90
(...)

This issue was also present on esp idf, but it was solved with esp-idf 2.1. ( i think it was an issue with the wi-fi lib on esp-idf )

Micropython-esp32 (relevant) config that i'm using:

ESPIDF_SUPHASH := 9b955f4c9f1b32652ea165d3e4cdaad01bba170e
#define CONFIG_MBEDTLS_HARDWARE_AES 0
#define CONFIG_MBEDTLS_HARDWARE_MPI 0
#define CONFIG_MBEDTLS_HARDWARE_SHA 0 

(hardware accelerations were disabled while testing because there's a known issue between them and the ssl handshakes : https://github.com/espressif/esp-idf/issues/630#issuecomment-304874107 )

[dpgeorge]

In 2d775fb87f2a8a4ce7b8ea659c6709bbb1f4c797 the code has been updated to use the latest ESP IDF. @LupascuAndrei do you want to check that ssl now works without a large delay?

BTW: we use unicore mode so the crypto HW bug is not an issue.

[LupascuAndrei]

Seems fixed, thank you. That was fast ! :D 6200 handshakes so far and none of them took more than 5.23s.

The average non stuck time spent is somewhere around ~1s; down from the previous 1.3s average it was before your commit. ( non-stuck = doesn't randomly hang for several seconds )

It's still making handshakes,I will come back with results once it reaches ~30k handshakes.

[LupascuAndrei]

It seems fixed now, thank you a lot.

results after 21k handshakes:

number of handshakes done so far: 21124
number of handshakes longer than 7 seconds: 1
average time spent on handshakes: 1.03736034783 seconds
longest handshake: 9.443 seconds

Later edit:

number of handshakes done so far: 55234
number of handshakes longer than 10 seconds: 1
average time spent on handshakes: 1.077458666 seconds
longest handshake: 14.09 seconds