javasslopenssldtlssslengine

javax.ssl: DTLS client received server hello done, but when server finished message comes, says it was not received


I've been working on a DTLS client/server implementation loosely based off of OpenJDK's DTLSOverDatagram, and successfully got my unit test where the handshake occurs to run successfully on my windows VM. I pushed my changes, and tried running the same test locally on my macbook. Interestingly, I got different results, and the handshake did not resolve well. The server finished, but the client ended up in a state where it kept trying to send handshake packets. Below is an image which shows all of the "produced" and "consuming" messages from javax.net.ssl. The sequence gets all the way to server finished, but the client does not consume it.

enter image description here

Instead, the client says:

javax.net.ssl|DEBUG|41|nioEventLoopGroup-5-1|2024-02-05 09:09:15.893 PST|DTLSInputRecord.java:1392|Not yet got the ServerHelloDone message
javax.net.ssl|DEBUG|41|nioEventLoopGroup-5-1|2024-02-05 09:09:15.893 PST|DTLSInputRecord.java:1044|The handshake flight is not ready to use: 2

But the client consumed the server hello done message already.

If anyone is brave enough to hunt for a potential bug in my handshake method, it would be most welcome, but otherwise if anyone suspects any glaring indications based on these logs, that is welcome too. Handhshake code:

public List<ByteBuffer> handshake(List<ByteBuffer> incoming) throws Exception {

    boolean spin = true;

    int loops = 0;

    ByteBuffer iNet = null;

    outgoing = new LinkedList<>();

    while (spin && !exceptionOccurred.get()) {

        loops++;

        SSLEngineResult.HandshakeStatus hs = engine.getHandshakeStatus();
        log.debug("{} Handshake status is {} loops {}.", getRole(), hs, loops);

        try {
            switch (hs) {
                case NEED_WRAP: {
                    boolean finished = produceHandshakePackets();
                    if (finished) {
                        completed = true;
                    }
                }
                break;
                case NEED_TASK: {
                    runDelegatedTasks();
                }
                break;
                case FINISHED: {
                    throw new Exception("Unexpected status, SSLEngine.getHandshakeStatus() shouldn't return FINISHED.");
                }
                case NOT_HANDSHAKING: {
                    log.debug("{} Handshake status is NOT_HANDSHAKING, finish the loop.", getRole());
                    completed = true;
                    spin = false;
                }
                break;
                case NEED_UNWRAP:
                case NEED_UNWRAP_AGAIN:
                default: {
                    log.debug("{} {} loops {}.", getRole(), hs, loops);

                    ByteBuffer iApp;
                    if (hs == SSLEngineResult.HandshakeStatus.NEED_UNWRAP) {

                        iNet = (iNet != null && iNet.hasRemaining()) ? iNet : (incoming.size() > 0 ? incoming.remove(0) : null);

                        if (iNet == null) {
                            boolean finished = onReceiveTimeout();
                            if (finished) {
                                completed = true;
                            }
                            spin = false;
                            continue;
                        } else if (buffered != null) {
                            iNet = ByteBuffer.allocate(buffered.remaining() + iNet.remaining()).put(buffered).put(iNet).flip();
                            buffered = null;
                        }
                    } else {
                        iNet = ByteBuffer.allocate(0);
                    }

                    iApp = ByteBuffer.allocate(32768);

                    SSLEngineResult r = engine.unwrap(iNet, iApp);

                    hs = r.getHandshakeStatus();

                    verifySSLEngineResultStatus(r);

                    if (status == SSLEngineResult.Status.BUFFER_UNDERFLOW && iNet.hasRemaining()) {
                        buffered = iNet;
                        spin = false;
                    }

                    log.debug("{} remaining: {}.", getRole(), iNet.remaining());
                    if (hs == SSLEngineResult.HandshakeStatus.FINISHED) {
                        completed = true;
                    }
                }
            }
        } catch (Exception ex) {
            setExceptionOccurred(ex);
        }

        try {
            if (completed) {

                hs = engine.getHandshakeStatus();

                log.debug("{} Handshake finished, status is {}.", getRole(), hs);

                if (engine.getHandshakeSession() != null) {
                    throw new Exception("Handshake finished, but handshake session is not null");
                }

                SSLSession session = engine.getSession();

                if (session == null) {
                    throw new Exception("Handshake finished, but session is null");
                }

                log.info("Session {} is valid: {}", session.getId(), session.isValid());

                log.debug("{} Negotiated protocol is {} and cipher suite is {}.", getRole(), session.getProtocol(), session.getCipherSuite());

                // handshake status should be NOT_HANDSHAKING
                //
                // According to the spec, SSLEngine.getHandshakeStatus() can't
                // return FINISHED.
                if (hs != SSLEngineResult.HandshakeStatus.NOT_HANDSHAKING) {
                    throw new Exception("Unexpected handshake status " + hs);
                }

                // Set the duration to complete.
                handshakeDuration = Duration.ofMillis(System.currentTimeMillis() - handshakeT0);
            }
        } catch (Exception ex) {
            setExceptionOccurred(ex);
        }
    }

    return outgoing;
}

Produce handshake packets method:

boolean produceHandshakePackets() throws Exception {

        boolean endLoops = false;
        int loops = 0;
        while (!endLoops && !exceptionOccurred.get()) {

            ByteBuffer oNet = ByteBuffer.allocate(32768);
            ByteBuffer oApp = ByteBuffer.allocate(0);
            SSLEngineResult r = engine.wrap(oApp, oNet);
            oNet.flip();

            status = r.getStatus();
            SSLEngineResult.HandshakeStatus hs = r.getHandshakeStatus();

            log.debug("{} ----produce handshake packet({}, {}, {})----", getRole(), ++loops, status, hs);

            verifySSLEngineResultStatus(r);

            if (oNet.hasRemaining()) {
                log.debug("{} Producing packet of length {}.", getRole(), oNet.remaining());
                outgoing.add(oNet);
            }

            if (hs == SSLEngineResult.HandshakeStatus.FINISHED) {
                log.debug("{} Produce handshake packets: Handshake status is FINISHED, finish the loop", getRole());
                return true;
            }

            boolean endInnerLoop = false;
            SSLEngineResult.HandshakeStatus nhs = hs;
            while (!endInnerLoop) {
                log.debug("{} Producing handshake packets ... handshake state: {}.", getRole(), nhs);
                switch (nhs) {
                    case NEED_TASK: {
                        runDelegatedTasks();
                    }
                    break;
                    case FINISHED: {
                        throw new Exception("Unexpected status, SSLEngine.getHandshakeStatus() should not return FINISHED");
                    }
                    case NEED_WRAP: {
                        endInnerLoop = true;
                    }
                    break;
                    default:
                    case NEED_UNWRAP:
                    case NEED_UNWRAP_AGAIN:
                    case NOT_HANDSHAKING: {
                        endInnerLoop = true;
                        endLoops = true;
                    }
                }

                nhs = engine.getHandshakeStatus();
            }
        }

        return false;
    }

Solution

  • I'm actually dumbfounded that this ended up being the cause, but I learned that Netty's default receive buffer is DEFAULT_RCVBUF_ALLOCATOR = new FixedRecvByteBufAllocator(2048);.

    Increasing the size of this channel option stopped the "new session ticket" message from becoming truncated.

    There was another bug, where onReceiveTimeout() being called in my code was calling produceHandshakePackets() which led to the client and server bombarding each other with duplicate messages.