Random error in HelloVerifyRequest()

[JotaPel23]

NOTE: Please use stackoverflow for support questions. This repository's issues are reserved for feature requests and bug reports.

I am submitting a …

• [x] bug report
• [ ] feature request

Description

I frequently receive this error when trying to connect to the test server.py with a communications module:

Traceback (most recent call last):
  File "/home/residentes/dtls/server_aux.py", line 231, in <module>
    main(parse_args())
  File "/home/residentes/dtls/server_aux.py", line 223, in main
    srv.run(partial(echo_handler, packet_size=4069))
  File "/home/residentes/dtls/server_aux.py", line 134, in run
    self._run(conn_handler)
  File "/home/residentes/dtls/server_aux.py", line 139, in _run
    with self._make_connection(self._sock) as conn:
  File "/home/residentes/dtls/server_aux.py", line 68, in _make_dtls_connection
    conn.do_handshake() #si quito esto me sale un wantederror
  File "/usr/local/lib/python3.10/dist-packages/mbedtls/tls.py", line 440, in do_handshake
    self._buffer.do_handshake()
  File "src/mbedtls/_tls.pyx", line 1268, in mbedtls._tls.MbedTLSBuffer.do_handshake
  File "src/mbedtls/_tls.pyx", line 1285, in mbedtls._tls.MbedTLSBuffer._handle_handshake_response
mbedtls._tls.HelloVerifyRequest: HelloVerifyRequest() 

It happens randomly, since many other times the operation is correct and also, when I try it with the test client it always works fine.

Investigating here I have seen that it may be due to a call that should not occur to mbedtls_ssl_close_notify, due to some problem with response times in handshaking, but I don't know how this can be modified on the server.

Current behavior

The error occurs about 50 percent of the times I try to connect to the server from a communications module with a SIM card.

Expected behavior

Successful handshake every time.

Steps to reproduce

1. Start the server: python3 server.py --dtls --address xx.xx.xx.xx --port xxx --debug 3 --psk-store CLI1=010f0304050607083

2. I start the communications module and try to connect with the server.

Minimal demo of the problem

ssl_srv.c:4511: server state: 0
ssl_msg.c:2033: => flush output
ssl_msg.c:2042: <= flush output
ssl_srv.c:4511: server state: 1
ssl_msg.c:2033: => flush output
ssl_msg.c:2042: <= flush output
ssl_srv.c:1397: => parse client hello
ssl_msg.c:1835: => fetch input
ssl_msg.c:1881: in_left: 0, nb_want: 5
ssl_msg.c:1920: f_recv_timeout: 0 ms
ssl_srv.c:4511: server state: 1
ssl_msg.c:2033: => flush output
ssl_msg.c:2042: <= flush output
ssl_srv.c:1397: => parse client hello
ssl_msg.c:1835: => fetch input
ssl_msg.c:1881: in_left: 0, nb_want: 5
ssl_msg.c:1920: f_recv_timeout: 0 ms
ssl_msg.c:1929: ssl->f_recv(_timeout)() returned 117 (-0xffffff8b)
ssl_msg.c:2020: <= fetch input
ssl_srv.c:1437: dumping 'record header' (13 bytes)
ssl_srv.c:1437: 0000:  16 fe fd 00 00 00 00 00 00 00 01 00 68           ............h
ssl_srv.c:1448: client hello v3, message type: 22
ssl_srv.c:1456: client hello v3, message len.: 104
ssl_srv.c:1459: client hello v3, protocol version: [254:253]
ssl_msg.c:1835: => fetch input
ssl_msg.c:1881: in_left: 117, nb_want: 117
ssl_msg.c:1889: <= fetch input
ssl_srv.c:1534: dumping 'record contents' (104 bytes)
ssl_srv.c:1534: 0000:  01 00 00 5c 00 00 00 00 00 00 00 5c fe fd 65 60  ...\.......\..e`
ssl_srv.c:1534: 0010:  5d b8 cf 47 51 7c 61 a8 37 f8 92 22 99 71 95 2e  ]..GQ|a.7..".q..
ssl_srv.c:1534: 0020:  95 10 aa 19 65 76 86 76 78 01 74 0c 40 ad 00 00  ....ev.vx.t.@...
ssl_srv.c:1534: 0030:  00 18 00 a9 c0 a5 00 af 00 8d c0 a9 00 a8 c0 a4  ................
ssl_srv.c:1534: 0040:  00 ae 00 8c c0 a8 00 8b 00 ff 01 00 00 1a 00 0d  ................
ssl_srv.c:1534: 0050:  00 16 00 14 06 03 06 01 05 03 05 01 04 03 04 01  ................
ssl_srv.c:1534: 0060:  03 03 03 01 02 03 02 01                          ........
ssl_srv.c:1551: client hello v3, handshake type: 1
ssl_srv.c:1558: client hello v3, handshake len.: 92
ssl_srv.c:1608: fragment_offset=0 fragment_length=92 length=92
ssl_srv.c:1653: dumping 'client hello, version' (2 bytes)
ssl_srv.c:1653: 0000:  fe fd                                            ..
ssl_srv.c:1682: dumping 'client hello, random bytes' (32 bytes)
ssl_srv.c:1682: 0000:  65 60 5d b8 cf 47 51 7c 61 a8 37 f8 92 22 99 71  e`]..GQ|a.7..".q
ssl_srv.c:1682: 0010:  95 2e 95 10 aa 19 65 76 86 76 78 01 74 0c 40 ad  ......ev.vx.t.@.
ssl_srv.c:1699: dumping 'client hello, session id' (0 bytes)
ssl_srv.c:1722: dumping 'client hello, cookie' (0 bytes)
ssl_srv.c:1734: cookie verification failed
ssl_srv.c:1773: dumping 'client hello, ciphersuitelist' (24 bytes)
ssl_srv.c:1773: 0000:  00 a9 c0 a5 00 af 00 8d c0 a9 00 a8 c0 a4 00 ae  ................
ssl_srv.c:1773: 0010:  00 8c c0 a8 00 8b 00 ff                          ........
ssl_srv.c:1792: dumping 'client hello, compression' (1 bytes)
ssl_srv.c:1792: 0000:  00                                               .
ssl_srv.c:1842: dumping 'client hello extensions' (26 bytes)
ssl_srv.c:1842: 0000:  00 0d 00 16 00 14 06 03 06 01 05 03 05 01 04 03  ................
ssl_srv.c:1842: 0010:  04 01 03 03 03 01 02 03 02 01                    ..........
ssl_srv.c:1892: found signature_algorithms extension
ssl_srv.c:0292: client hello v3, signature_algorithm ext: match sig 4 and hash 8
ssl_srv.c:0292: client hello v3, signature_algorithm ext: match sig 1 and hash 8
ssl_srv.c:0292: client hello v3, signature_algorithm ext: match sig 4 and hash 7
ssl_srv.c:0292: client hello v3, signature_algorithm ext: match sig 1 and hash 7
ssl_srv.c:0292: client hello v3, signature_algorithm ext: match sig 4 and hash 6
ssl_srv.c:0292: client hello v3, signature_algorithm ext: match sig 1 and hash 6
ssl_srv.c:0292: client hello v3, signature_algorithm ext: match sig 4 and hash 5
ssl_srv.c:0292: client hello v3, signature_algorithm ext: match sig 1 and hash 5
ssl_srv.c:0296: client hello v3, signature_algorithm ext: hash alg 4 not supported
ssl_srv.c:0296: client hello v3, signature_algorithm ext: hash alg 4 not supported
ssl_srv.c:2082: received TLS_EMPTY_RENEGOTIATION_INFO
ssl_srv.c:1012: trying ciphersuite: 0x8c (TLS-PSK-WITH-AES-128-CBC-SHA)
ssl_srv.c:2192: selected ciphersuite: TLS-PSK-WITH-AES-128-CBC-SHA
ssl_msg.c:0067: set_timer to 0 ms
ssl_srv.c:2217: no hash algorithm for signature algorithm 0 - should not happen
ssl_srv.c:2223: <= parse client hello
ssl_srv.c:4511: server state: 2
ssl_msg.c:2033: => flush output
ssl_msg.c:2042: <= flush output
ssl_srv.c:2755: => write server hello
ssl_srv.c:2760: client hello was not authenticated
ssl_srv.c:2761: <= write server hello
ssl_srv.c:2631: => write hello verify request
ssl_srv.c:2644: dumping 'server version' (2 bytes)
ssl_srv.c:2644: 0000:  fe fd                                            ..
ssl_srv.c:2665: dumping 'cookie sent' (32 bytes)
ssl_srv.c:2665: 0000:  65 60 5d ba 9b 17 54 7c d9 99 6a 9c ca 96 6a e1  e`]...T|..j...j.
ssl_srv.c:2665: 0010:  49 18 b1 35 f0 23 c8 e8 fd ff 63 1a 93 f2 ff db  I..5.#....c.....
ssl_msg.c:2451: => write handshake message
ssl_msg.c:2097: => ssl_flight_append
ssl_msg.c:2098: dumping 'message appended to flight' (47 bytes)
ssl_msg.c:2098: 0000:  03 00 00 23 00 00 00 00 00 00 00 23 fe fd 20 65  ...#.......#.. e
ssl_msg.c:2098: 0010:  60 5d ba 9b 17 54 7c d9 99 6a 9c ca 96 6a e1 49  `]...T|..j...j.I
ssl_msg.c:2098: 0020:  18 b1 35 f0 23 c8 e8 fd ff 63 1a 93 f2 ff db     ..5.#....c.....
ssl_msg.c:2132: <= ssl_flight_append
ssl_msg.c:2575: <= write handshake message
ssl_msg.c:2222: => mbedtls_ssl_flight_transmit
ssl_msg.c:2225: initialise flight transmission
ssl_msg.c:2164: skip swap epochs
ssl_msg.c:2326: dumping 'handshake header' (12 bytes)
ssl_msg.c:2326: 0000:  03 00 00 23 00 00 00 00 00 00 00 23              ...#.......#
ssl_msg.c:2598: => write record
ssl_msg.c:2703: output record: msgtype = 22, version = [254:253], msglen = 47
ssl_msg.c:2708: dumping 'output record sent to network' (60 bytes)
ssl_msg.c:2708: 0000:  16 fe fd 00 00 00 00 00 00 00 01 00 2f 03 00 00  ............/...
ssl_msg.c:2708: 0010:  23 00 00 00 00 00 00 00 23 fe fd 20 65 60 5d ba  #.......#.. e`].
ssl_msg.c:2708: 0020:  9b 17 54 7c d9 99 6a 9c ca 96 6a e1 49 18 b1 35  ..T|..j...j.I..5
ssl_msg.c:2708: 0030:  f0 23 c8 e8 fd ff 63 1a 93 f2 ff db              .#....c.....
ssl_msg.c:2743: Still 16324 bytes available in current datagram
ssl_msg.c:2756: <= write record
ssl_msg.c:2033: => flush output
ssl_msg.c:2047: message length: 60, out_left: 60
ssl_msg.c:2054: ssl->f_send() returned 60 (-0xffffffc4)
ssl_msg.c:2081: <= flush output
ssl_msg.c:0067: set_timer to 0 ms
ssl_msg.c:2367: <= mbedtls_ssl_flight_transmit
ssl_srv.c:2686: <= write hello verify request
ssl_srv.c:4511: server state: 18
ssl_msg.c:2033: => flush output
ssl_msg.c:2042: <= flush output
ssl_msg.c:0067: set_timer to 0 ms
ssl_msg.c:0067: set_timer to 0 ms
ssl_msg.c:5612: => write close notify
ssl_msg.c:5623: <= write close notify
Traceback (most recent call last):
  File "/home/residentes/dtls/server_aux.py", line 231, in <module>
    main(parse_args())
  File "/home/residentes/dtls/server_aux.py", line 223, in main
    srv.run(partial(echo_handler, packet_size=4069))
  File "/home/residentes/dtls/server_aux.py", line 134, in run
    self._run(conn_handler)
  File "/home/residentes/dtls/server_aux.py", line 139, in _run
    with self._make_connection(self._sock) as conn:
  File "/home/residentes/dtls/server_aux.py", line 68, in _make_dtls_connection
    conn.do_handshake() 
  File "/usr/local/lib/python3.10/dist-packages/mbedtls/tls.py", line 440, in do_handshake
    self._buffer.do_handshake()
  File "src/mbedtls/_tls.pyx", line 1268, in mbedtls._tls.MbedTLSBuffer.do_handshake
  File "src/mbedtls/_tls.pyx", line 1285, in mbedtls._tls.MbedTLSBuffer._handle_handshake_response
mbedtls._tls.HelloVerifyRequest: HelloVerifyRequest()

[Synss]

Thank you for your report and already spending some time on investigating the problem.

Investigating here I have seen that it may be due to a call that should not occur to mbedtls_ssl_close_notify, due to some problem with response times in handshaking, but I don't know how this can be modified on the server.

The only place where the library sends the mbedtls_ssl_close_notify is in MbedTLSBuffer.shutdown(). I also see that TLSWrappedSocket.close() calls TLSWrappedBuffer.shutdown(). That may be the origin of this bug. I'm not entirely sure. Could you try to remove this line and try again?

That would be this line: https://github.com/Synss/python-mbedtls/blob/master/src/mbedtls/tls.py#L320

Since I can't reproduce this bug, I'll have to rely on you for testing.

[JotaPel23]

Thank you very much for your help.

I have tried commenting that line and it continues to give me the same errors. Is there any possibility to manage server response times during hansaking? We are trying to make the connection with UDP and NBiot modules and we think that it may be a network problem due to the timings, because it is very strange that sometimes the connection works and sometimes it doesn't.

I'm trying modifying these parameters in the DTLS configuration, but it doesn't seem to fix the problem either:

conf = DTLSConfiguration(
             handshake_timeout_min = 1,
             handshake_timeout_max = 60000.0,
             ciphers=( "TLS-PSK-WITH-AES-128-CBC-SHA",),
             pre_shared_key_store=args.psk_store, validate_certificates=False                       
         )

[Synss]

The settings you’re changing are the ones. Now, if it’s really a timing issue, it can be reproduced by instrumenting the code. You could try to make the handshake slower by adding sleep calls in do_handshake() or even fake a slow overall communication by instrumenting buffer_write and buffer_read. For the buffer_*, you will need to take the Gil, probably,

with gil:
    import time
    time.sleep(…

I would really like to get the hardware out of the way because my experience with embedded is that the vendors do not always implement their stack correctly. Although some do, obviously. 😄

When you say it is slow: how slow is the communication exactly? How long does a successful handshake take?

Finally, any chance you’d be able to try TLS as well? A TLS handshake is actually simpler.

[Synss]

Actually, the HelloVerifyRequest exception is a normal step during the DTLS handshake. Are you sure that you’ve implemented the server correctly? 🤔

Have a look at _make_dtls_connection in programs/server.py.

You can certainly control that client and server are indeed correct without extra hardware.

[JotaPel23]

Thank you very much again for helping me.

I have done a lot of tests and I have not been able to get it to work correctly with the communications module. I think it has to be something about the network latency, because for example with a SIM from one company it works almost always for me and with another SIM from another company it has not worked even once. Using the library's example client and server on local server works every time.

I tried what you told me about sleeps and it worked even worse, so I understand that what is happening is that the module runs too fast for the server. It makes many retries and I guess it doesn't wait the necessary time for my answers, or something like that.

On the other hand, I have the _make_dtls_connection exactly the same as in the example. So I guess that's not the problem either.

[Synss]

Well then, it's clearly a problem with the module. Either a hardware problem or a buggy implementation on their part. There really is nothing I can do.