[Bug]: DTLS 1.3 handshake can fail with `HRR_COOKIE_ERROR` when certain packets are dropped

[markasoftware]

Contact Details

mark@markasoftware.com

Version

5.9.1

Description

I maintain a side project I405 tunnel that uses wolfSSL DTLS 1.3. In our test suite is a fuzzy test that ensures the handshake can complete even when any two packets are dropped. After upgrading to wolfSSL 5.9.1 this test is failing in a new way: For many of the combinations of dropped packets, the handshake fails to complete due to the server giving error -505, HRR_COOKIE_ERROR: "Cookie does not match the one sent in HelloRetryRequest".

The issue is present in 5.9.1 but not 5.9.0. Using git bisect I determined that the commit c3289f8 which enables ML-KEM by default introduced the bug (though probably the bug would occur in older versions too, if I forced ML-KEM).

Last year, this exact same test detected bug #8855

@rizlik I know you looked at bug #8855 last year using almost the same repro script, so maybe it'll be easiest for you to debug or fix this one?

Reproduction steps

1. ./configure --enable-dtls --enable-dtls13 --enable-psk --enable-dtls-frag-ch --enable-static
2. make CFLAGS=-fno-lto
3. Download wolfssl-repro.c
4. Compile with gcc -o repro wolfssl-repro.c src/.libs/libwolfssl.a -lm -I.
5. Run ./repro, observe the handshake does not complete due to error -505, ie HRR_COOKIE_ERROR "Cookie does not match one sent in HelloRetryRequest"

The repro script linked above was written by an LLM based on the (human-written) source code in my project. If you want to run the upstream failing test, you can:

1. clone my repo https://github.com/markasoftware/i405-tunnel at commit 6cabbd53c22933dbf2ed9e0f8d2f71f91340206a
2. remove this line
3. run cargo test --features wolfssl-debug -- --ignored long_distance_reorder::_2_3_false

Relevant log output

This is from the standalone repro script above (not i405 tunnel), and contains interleaved logs from that script and from wolfssl:

Initial ClientHello generation
IOCallbacks send: Ok(262 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
[client] Has outgoing packet (262 bytes), packet_id 0
[client] Queuing packet_id 0 for other side
Entering handshake loop (pre-sleep, max 30 iterations)
Handshake iteration (pre-sleep): 1
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
[server] Processing incoming packet (262 bytes) from queue
IOCallbacks recv: Ok(262 bytes)
IOCallbacks send: Ok(152 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
[server] Has outgoing packet (152 bytes), packet_id 1
[server] Queuing packet_id 1 for other side
Handshake iteration (pre-sleep): 2
[client] Processing incoming packet (152 bytes) from queue
IOCallbacks recv: Ok(152 bytes)
IOCallbacks send: Ok(1400 bytes)
IOCallbacks send: WouldBlock (last_sent_packet is Some)
[client] try_negotiate: PendingWrite (WouldBlock)
[client] Has outgoing packet (1400 bytes), packet_id 2
[client] DROPPING packet_id 2
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
Handshake iteration (pre-sleep): 3
IOCallbacks send: Ok(631 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
[client] Has outgoing packet (631 bytes), packet_id 3
[client] DROPPING packet_id 3
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
Handshake iteration (pre-sleep): 4
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
No progress in pre-sleep iteration 4 and queues empty. Breaking early.
Simulating 1010ms sleep for wolfSSL internal timers...
Handshake not complete after sleep. Explicitly handling timeouts.
[client] Explicitly handling timeout. Current wolfSSL timeout: 1
[client] dtls_has_timed_out: Ready(false) - timeout processed.
[client] Calling try_negotiate after dtls_has_timed_out
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate after timeout: PendingRead (WouldBlock)
[server] Explicitly handling timeout. Current wolfSSL timeout: 1
[server] dtls_has_timed_out: Ready(false) - timeout processed.
[server] Calling try_negotiate after dtls_has_timed_out
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate after timeout: PendingRead (WouldBlock)
Entering handshake loop (post-sleep, max 30 iterations)
Handshake iteration (post-sleep): 1
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
No progress in post-sleep iteration 1 and queues empty. Breaking early.
Simulating 1010ms sleep for wolfSSL internal timers...
Handshake not complete after sleep. Explicitly handling timeouts.
[client] Explicitly handling timeout. Current wolfSSL timeout: 1
IOCallbacks send: Ok(262 bytes)
IOCallbacks send: WouldBlock (last_sent_packet is Some)
[client] dtls_has_timed_out: PendingWrite - wants to send.
[client] Calling try_negotiate after dtls_has_timed_out
IOCallbacks send: WouldBlock (last_sent_packet is Some)
[client] try_negotiate after timeout: PendingWrite (WouldBlock)
[client] (After timeout) Has outgoing packet (262 bytes), packet_id 4
[client] (After timeout) Queuing packet_id 4
[server] Explicitly handling timeout. Current wolfSSL timeout: 2
[server] dtls_has_timed_out: Ready(false) - timeout processed.
[server] Calling try_negotiate after dtls_has_timed_out
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate after timeout: PendingRead (WouldBlock)
Entering handshake loop (post-sleep, max 30 iterations)
Handshake iteration (post-sleep): 1
IOCallbacks send: Ok(1400 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
[client] Has outgoing packet (1400 bytes), packet_id 5
[client] Queuing packet_id 5 for other side
[server] Processing incoming packet (262 bytes) from queue
IOCallbacks recv: Ok(262 bytes)
IOCallbacks send: Ok(152 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
[server] Has outgoing packet (152 bytes), packet_id 6
[server] Queuing packet_id 6 for other side
Handshake iteration (post-sleep): 2
[client] Processing incoming packet (152 bytes) from queue
IOCallbacks recv: Ok(152 bytes)
IOCallbacks send: Ok(31 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
[client] Has outgoing packet (31 bytes), packet_id 7
[client] Queuing packet_id 7 for other side
[server] Processing incoming packet (1400 bytes) from queue
IOCallbacks recv: Ok(1400 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
Handshake iteration (post-sleep): 3
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
[server] Processing incoming packet (31 bytes) from queue
IOCallbacks recv: Ok(31 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
No progress in post-sleep iteration 3 and queues empty. Breaking early.
Simulating 1010ms sleep for wolfSSL internal timers...
Handshake not complete after sleep. Explicitly handling timeouts.
[client] Explicitly handling timeout. Current wolfSSL timeout: 1
[client] dtls_has_timed_out: Ready(false) - timeout processed.
[client] Calling try_negotiate after dtls_has_timed_out
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate after timeout: PendingRead (WouldBlock)
[server] Explicitly handling timeout. Current wolfSSL timeout: 1
[server] dtls_has_timed_out: Ready(false) - timeout processed.
[server] Calling try_negotiate after dtls_has_timed_out
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate after timeout: PendingRead (WouldBlock)
Entering handshake loop (post-sleep, max 30 iterations)
Handshake iteration (post-sleep): 1
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate: PendingRead (WouldBlock)
No progress in post-sleep iteration 1 and queues empty. Breaking early.
Simulating 1010ms sleep for wolfSSL internal timers...
Handshake not complete after sleep. Explicitly handling timeouts.
[client] Explicitly handling timeout. Current wolfSSL timeout: 1
IOCallbacks send: Ok(262 bytes)
IOCallbacks send: WouldBlock (last_sent_packet is Some)
[client] dtls_has_timed_out: PendingWrite - wants to send.
[client] Calling try_negotiate after dtls_has_timed_out
IOCallbacks send: WouldBlock (last_sent_packet is Some)
[client] try_negotiate after timeout: PendingWrite (WouldBlock)
[client] (After timeout) Has outgoing packet (262 bytes), packet_id 8
[client] (After timeout) Queuing packet_id 8
[server] Explicitly handling timeout. Current wolfSSL timeout: 1
[server] dtls_has_timed_out: Ready(false) - timeout processed.
[server] Calling try_negotiate after dtls_has_timed_out
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[server] try_negotiate after timeout: PendingRead (WouldBlock)
Entering handshake loop (post-sleep, max 30 iterations)
Handshake iteration (post-sleep): 1
IOCallbacks send: Ok(631 bytes)
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
[client] Has outgoing packet (631 bytes), packet_id 9
[client] Queuing packet_id 9 for other side
[server] Processing incoming packet (262 bytes) from queue
IOCallbacks recv: Ok(262 bytes)
IOCallbacks send: Ok(15 bytes)
[server] try_negotiate error: -505
Handshake iteration (post-sleep): 2
IOCallbacks recv: WouldBlock (next_packet_to_receive is None)
[client] try_negotiate: PendingRead (WouldBlock)
[server] Processing incoming packet (631 bytes) from queue
[server] try_negotiate error: -505
No progress in post-sleep iteration 2 and queues empty. Breaking early.
Handshake did NOT complete.
  Client init finished: 0
  Server init finished: 0
  Packet ID counter: 10
  C->S queue: 0, S->C queue: 0

[rizlik]

Hi @markasoftware,

thanks for the report. I'll look in to it and let you know.