Receiving SSH_MSG_UNIMPLEMENTED occasionally during key exchange

[rasantel]

I found in our application logs several instances of SSHJ connection errors due to receiving SSH_MSG_UNIMPLEMENTED from an OpenSSH server. The server logs show that, in each case, it receives an extra KEXINIT from the client, which causes it to respond with the unimplemented message.

The SSHJ version is 0.35.0. It has the fix for #810, which addressed this issue to a large extent, but not completely. Interestingly, the keep alive thread was not enabled in our application.

I don't have direct access to monitor the production system, but I am able to reproduce the issue locally with the help of debugger breakpoints (to force specific thread interleavings) or injected thread sleeps, and an openssh 8.9p1-3ubuntu0.1 server running on the same machine. The test program is:

    try (SSHClient client = new SSHClient()) {
        client.addHostKeyVerifier(new PromiscuousVerifier());
        client.connect("localhost");
    }

This test will normally pass. But if you put a breakpoint at https://github.com/hierynomus/sshj/blob/v0.35.0/src/main/java/net/schmizz/sshj/SSHClient.java#L815 and wait for a second or two before resuming execution, or add a Thread.sleep(1000) before that line, the program will hit a net.schmizz.sshj.transport.TransportException: Received SSH_MSG_UNIMPLEMENTED while exchanging keys.

The reason why this happens is that, if the reader thread get a KEXINIT first and completes the key exchange before the main thread is ready to start its own key exchange, the main thread at KeyExchanger.startKex will think that it's ok to proceed because by then kexOngoing is back to false. Note that the check trans.isKeyExchangeRequired() earlier in SSHClient.onConnect() helps detect that the reader thread is already exchanging keys, but if it's called before the reader thread starts the exhange, it will return true and allow the main thread to proceed with the key exchange.

In other words, the sequence of events is:

1. trans.isKeyExchangeRequired() returns true in the main thread, so the main thread calls doKex.
2. The reader thread receives a KEXINIT and completes the key exchange with the server.
3. The main thread reaches KeyExchanger.startKex and initiates a new key exchange because kexOngoing is back to false.
4. The server responds with an UNIMPLEMENTED message,

I realize that this sequence requires a very unusual, uneven allocation of CPU time to the two threads; the reader, despite several messages back and forth with the server, completes the key exchange between the main thread's call to isKeyExchangeRequired and startKex. It's possible that some other race condition caused the observed SSH_MSG_UNIMPLEMENTED errors, but I haven't found another one so far.

I have a tentative fix that I will post as a PR.

[hierynomus]

Wow, thanks for the detailed bug report! If only everyone who found a bug would be so thorough, this would make lives of Open Source developers so much easier! Really appreciate the effort you put into getting to the bottom of this. Timing issues can be a real PITA to find ;)

Looking forward to the PR! If that's half as good as your bug report I'm already a happy developer!

[hierynomus]

The PR has been merged and released, closing this ticket