Received SSH_MSG_UNIMPLEMENTED while exchanging keys with KeepAlive Enabled

[exceptionfactory]

Starting several SSH connections across multiple threads can result in an SSH server sending SSH_MSG_UNIMPLEMENTED during key exchange as shown in the follow error log:

ERROR net.schmizz.sshj.transport.TransportImpl - Dying because - Received SSH_MSG_UNIMPLEMENTED while exchanging keys
net.schmizz.sshj.transport.TransportException: Received SSH_MSG_UNIMPLEMENTED while exchanging keys
	at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:565)
	at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:495)
	at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:113)
	at net.schmizz.sshj.transport.Decoder.received(Decoder.java:200)
	at net.schmizz.sshj.transport.Reader.run(Reader.java:60)

This appears to occur more frequently in SSHJ 0.33.0 and 0.34.0 with SSH KeepAlive enabled. These versions include changes in pull request #752, which start the KeepAlive Thread in SSHClient.onConnect().

The underlying problem appears to be related to the timing of sending and receiving SSH_MSG_KEXINIT packets. Sending an SSH_MSG_KEXINIT packet can be initiated from different locations. The SSHClient.onConnect() method calls Transport.doKex(), which calls KeyExchanger.startKex(). KexExchange.handle() can also call KeyExchanger.startKex() when receiving an SSH_MSG_KEXINIT packet. This can cause problems with multiple connections due to different threads calling KeyExchanger.startKex() at different times.

When an OpenSSH server receives an unexpected SSH_MSG_KEXINIT packet, it sends an SSH_MSG_UNIMPLEMENTED packet and logs the following error:

dispatch_protocol_error: type 20 seq 3 [preauth]

The atmoz/sftp Docker image provides a standard OpenSSH server for testing, but this issue should be reproducible with any recent version of OpenSSH server.

The nature of the problem makes it difficult to reproduce in a unit test, but the following class is capable of causing the error in the process of initiating multiple connection attempts using a pool of threads. The class attempts up to 1000 connections using a pool of four threads. It is not necessary to authenticate to the SSH server since the problem occurs during initial connection key exchange. The class relies of slf4j-simple and Java System properties for console logging. The connect method calls System.exit() at the first error encountered.

import net.schmizz.keepalive.KeepAliveProvider;
import net.schmizz.sshj.DefaultConfig;
import net.schmizz.sshj.SSHClient;
import net.schmizz.sshj.transport.verification.PromiscuousVerifier;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;

public class SshConnectCommand {

    static {
        System.setProperty("org.slf4j.simpleLogger.defaultLogLevel", "DEBUG");
        System.setProperty("org.slf4j.simpleLogger.showDateTime", "true");
        System.setProperty("org.slf4j.simpleLogger.dateTimeFormat", "yyyy-MM-dd HH:mm:ss.SSS");
    }

    private static final String SSH_SERVER = "127.0.0.1";
    private static final int SSH_PORT = 2222;

    private static final int KEEP_ALIVE_INTERVAL = 5;
    private static final int POOL_SIZE = 4;
    private static final int CONNECTIONS = 1000;
    private static final int EXECUTION_TIME = 10;

    private static final Logger logger = LoggerFactory.getLogger(SshConnectCommand.class);

    public static void main(String[] args) throws Exception {
        final ExecutorService executorService = Executors.newFixedThreadPool(POOL_SIZE);
        for (int i = 1; i <= CONNECTIONS; i++) {
            final int counter = i;
            executorService.execute(() -> {
                connect(counter);
            });
        }

        executorService.awaitTermination(EXECUTION_TIME, TimeUnit.SECONDS);
        executorService.shutdown();

        logger.info("Completed Connections [{}]", CONNECTIONS);
    }

    private static void connect(int counter) {
        try (final SSHClient sshClient = createClient()) {
            logger.info("Connection Starting [{}]", counter);
            sshClient.connect(SSH_SERVER, SSH_PORT);
        } catch (final Exception e) {
            logger.error("Connection Failed [{}]", counter, e);
            System.exit(1);
        } finally {
            logger.info("Connection Completed [{}]", counter);
        }
    }

    private static SSHClient createClient() {
        final DefaultConfig config = new DefaultConfig();
        config.setKeepAliveProvider(KeepAliveProvider.KEEP_ALIVE);
        final SSHClient sshClient = new SSHClient(config);

        sshClient.getConnection().getKeepAlive().setKeepAliveInterval(KEEP_ALIVE_INTERVAL);
        sshClient.addHostKeyVerifier(new PromiscuousVerifier());
        return sshClient;
    }
}

[hierynomus]

Fixed witht he merge of #811