Debug SSH Connection issue in key exchange

ssh_debug_x-raySecuring a server means hardening the SSH server settings, but doing so can also cause issues with ssh clients. Finding the cipher or algorithm causing a failled connection can be tricky. Depending on the client used, the error message might be very generic like “Failed to start SSH session”.

Using a openssh client will allow increasing the log level (-v) until the cause of the problem shows up in the output. Experience has shown that most issues are not related to openssh client configuration but closed source or third-party applications that provide less details via their user interface. In the case explained here it was an iPad/iPhone app, which had updated its ssh library. The app did not provide full details about the error as space is limited.

From the first error message “Failed to start SSH session: Unable to exchange encryption keys.” it was clear that there was a fundamental issue with the connection setup, but without any details from the client debugging had to be performed on the server side.

iOS_Failed_to_start_SSH_session

To debug the connection issue from the ssh daemon, the following log needs to be monitored on CentOS (other distributions might log to a different file).

$ tail /var/log/secure

In debian based distributions like Ubuntu, the log file for the ssh daemon is the following.

$ tail -f /var/log/auth.log

No matching MAC algorithem

The following line should be under the last lines of the log, indicating what the initial error message already suggested. Client and server could not setup a session as they could not agree on a MAC (message authentication code) algorithm.

... sshd[5176]: fatal: no matching mac found: client hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com server hmac-sha2-512,hmac-sha2-256

But this error message already shows us more detail. It lists the client and server offered MACs. The client offered 6 MACs and the server offered 2, but no MAC is in both lists.

To continue debugging the connection issues the following MAC algorithm was enabled in the ssh daemon configuration, chosen at random from the client offered MAC algorithms. The resulting ssh daemon configuration after applying the settings from hardening the SSH server settings and with the added MAC algorithm looks like this.

# Hardening SSH configuration
KexAlgorithms ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256
MACs hmac-sha2-512,hmac-sha2-256,hmac-ripemd160
Ciphers aes256-ctr,aes192-ctr,aes128-ctr

After changing the configuration of the ssh daemon, sshd needs to be instructed to reload its configuration.

$ service sshd reload

The next connection attempt shows the agreed MAC algorithm in “hmac-ripemd160” the log clearly.

... sshd[634]: debug2: mac_setup: found hmac-ripemd160

No matching KEX algorithm

Even with the MAC algorithm agreed, the next problem might arise when the KEX (Key EXchange) algorithm can not be negotiated. The situation about the KEX negotiation is indicated very clearly.

... sshd[6260]: fatal: Unable to negotiate a key exchange method

Sadly this message does not provide any details about the proposed KEX algorithms from either side of the connection. To debug the connection on CentOS 6 running the OpenSSH 5.3 daemon, the debug level DEBUG2 is needed. To enable the logging on the ssh server, the following line of configuration has to be added to the /etc/ssh/sshd_config. It will not alter the behaviour of the ssh daemon itself, except to add additional logging to understand the decissions made during the connection setup. This configuration should be used with care on a busy ssh daemon as it increases the amount of logging significantly.

LogLevel DEBUG2

After changing the configuration of the ssh daemon, sshd needs to be instructed to reload its configuration again. The second command will open the log file to follow the login attempt.

$ service sshd reload
$ tail /var/log/secure

With the increased log level, a connection attempt will look similar to this example (here I have removed the beginning of each line where there would normally be a timestamp and the host name).

sshd[621]: debug1: Forked child 634.
sshd[634]: Set /proc/self/oom_score_adj to 0
sshd[634]: debug1: rexec start in 7 out 7 newsock 7 pipe 9 sock 10
sshd[634]: debug1: inetd sockets after dupping: 3, 3
sshd[634]: Connection from 123.123.123.123 port 36462
sshd[634]: debug1: Client protocol version 2.0; client software version libssh2_1.7.0_DEV
sshd[634]: debug1: no match: libssh2_1.7.0_DEV
sshd[634]: debug1: Enabling compatibility mode for protocol 2.0
sshd[634]: debug1: Local version string SSH-2.0-OpenSSH_5.3
sshd[634]: debug2: fd 3 setting O_NONBLOCK
sshd[634]: debug2: Network child is on pid 634
sshd[634]: debug1: permanently_set_uid: 74/74
sshd[634]: debug1: list_hostkey_types: ssh-rsa,ssh-dss
sshd[634]: debug1: SSH2_MSG_KEXINIT sent
sshd[634]: debug1: SSH2_MSG_KEXINIT received
sshd[634]: debug2: kex_parse_kexinit:
ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256
sshd[634]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
sshd[634]: debug2: kex_parse_kexinit: aes256-ctr,aes192-ctr,aes128-ctr
sshd[634]: debug2: kex_parse_kexinit: aes256-ctr,aes192-ctr,aes128-ctr
sshd[634]: debug2: kex_parse_kexinit: hmac-sha2-512,hmac-sha2-256,hmac-ripemd160
sshd[634]: debug2: kex_parse_kexinit: hmac-sha2-512,hmac-sha2-256,hmac-ripemd160
sshd[634]: debug2: kex_parse_kexinit: none,zlib@openssh.com
sshd[634]: debug2: kex_parse_kexinit: none,zlib@openssh.com
sshd[634]: debug2: kex_parse_kexinit:
sshd[634]: debug2: kex_parse_kexinit:
sshd[634]: debug2: kex_parse_kexinit: first_kex_follows 0
sshd[634]: debug2: kex_parse_kexinit: reserved 0
sshd[634]: debug2: kex_parse_kexinit:
diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
sshd[634]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
sshd[634]: debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
sshd[634]: debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
sshd[634]: debug2: kex_parse_kexinit:
hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com
sshd[634]: debug2: kex_parse_kexinit:
hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com
sshd[634]: debug2: kex_parse_kexinit: none
sshd[634]: debug2: kex_parse_kexinit: none
sshd[634]: debug2: kex_parse_kexinit:
sshd[634]: debug2: kex_parse_kexinit:
sshd[634]: debug2: kex_parse_kexinit: first_kex_follows 0
sshd[634]: debug2: kex_parse_kexinit: reserved 0
sshd[634]: debug2: mac_setup: found hmac-ripemd160
sshd[634]: debug1: kex: client->server aes128-ctr hmac-ripemd160 none
sshd[634]: debug2: mac_setup: found hmac-ripemd160
sshd[634]: debug1: kex: server->client aes128-ctr hmac-ripemd160 none
sshd[634]: fatal: Unable to negotiate a key exchange method
sshd[634]: debug1: do_cleanup
sshd[634]: debug1: do_cleanup

There is no clear indication on the offered KEX algorithms in the log. To read this information out of the log, a deeper look into where the log lines come from is necessary. What’s interesting at this point are the log lines containing the “debug2: kex_parse_kexinit:”.

Digging into the logs

A quick peek into the function kex_buf2prop() of the file kex.c on branch V_5_3 of OpenSSH reads (shortened slightly) like this.

	...
for (...) {
debug2("kex_parse_kexinit: %s", proposal[i]);
}
debug2("kex_parse_kexinit: first_kex_follows %d ", i);
debug2("kex_parse_kexinit: reserved %u ", i);
...

The function is called from kex_choose_conf() found in the same file. As the simplified example shows, this function is calling the above method twice.

	...
my   = kex_buf2prop(&kex->my, NULL);
peer = kex_buf2prop(&kex->peer, &first_kex_follows);
...

Without digging deeper, the name of the parameters suggest, first the function is called with the locally configured algorithms and second with the offered algorithms from the remote. In this case, that would indicate that first the proposal from the ssh deamon is logged and the second block contains the proposal from the (remote) connecting client.

As such, the “kex_parse_kexinit” lines can be seperated into the following two blocks. The first one is the ssh daemon side.

sshd[634]: debug2: kex_parse_kexinit:
ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256
sshd[634]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
sshd[634]: debug2: kex_parse_kexinit: aes256-ctr,aes192-ctr,aes128-ctr
sshd[634]: debug2: kex_parse_kexinit: aes256-ctr,aes192-ctr,aes128-ctr
sshd[634]: debug2: kex_parse_kexinit: hmac-sha2-512,hmac-sha2-256,hmac-ripemd160
sshd[634]: debug2: kex_parse_kexinit: hmac-sha2-512,hmac-sha2-256,hmac-ripemd160
sshd[634]: debug2: kex_parse_kexinit: none,zlib@openssh.com
sshd[634]: debug2: kex_parse_kexinit: none,zlib@openssh.com
sshd[634]: debug2: kex_parse_kexinit:
sshd[634]: debug2: kex_parse_kexinit:
sshd[634]: debug2: kex_parse_kexinit: first_kex_follows 0
sshd[634]: debug2: kex_parse_kexinit: reserved 0
  • The 1st line appears to be the configured KEX algorithms (sshd_config option “KexAlgorithms”).
  • The 2nd line appears to be the configured host key algorithms (sshd_config option “HostKeyAlgorithms”).
  • The 3rd & 4th lines appear to be the configured ciphers (sshd_config option “Ciphers”).
  • The 5th & 6th lines appear to be the configured MAC algorithms (sshd_config option “MACs”).

For some reason, which would probably require a deeper understanding of the source, the cipher and MAC list is shown twice. The block of “kex_parse_kexinit” lines ends with the line “kex_parse_kexinit: reserved 0”.

The second block is the proposals from the remote side, which is the ssh client trying to connect.

sshd[634]: debug2: kex_parse_kexinit:
diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
sshd[634]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
sshd[634]: debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
sshd[634]: debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
sshd[634]: debug2: kex_parse_kexinit:
hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com
sshd[634]: debug2: kex_parse_kexinit:
hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com
sshd[634]: debug2: kex_parse_kexinit: none
sshd[634]: debug2: kex_parse_kexinit: none
sshd[634]: debug2: kex_parse_kexinit:
sshd[634]: debug2: kex_parse_kexinit:
sshd[634]: debug2: kex_parse_kexinit: first_kex_follows 0
sshd[634]: debug2: kex_parse_kexinit: reserved 0

Knowing this, we can see that the KEX algorithms from the ssh daemon and the client’s proposed KEX algorithms do not have any algorithms in common, which causes the error message we saw earlier.

Of course, enabling one of the client’s proposed KEX algorithms would allow the client to login, but enabling one of these MAC or KEX algorithms needs to be handled with care. Many of the disabled ciphers and algorithms might be disabled for security reasons as described in Harden the SSH server settings.

As a proof, one of the client’s proposed KEX  algorithms (I randomly chose “diffie-hellman-group-exchange-sha1”) can be enabled in the shh daemon. The configuration might look like this with the additional KEX algorithm.

# Hardening SSH configuration
KexAlgorithms ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1
MACs hmac-sha2-512,hmac-sha2-256,hmac-ripemd160
Ciphers aes256-ctr,aes192-ctr,aes128-ctr

After changing the configuration of the ssh daemon, sshd needs to be instructed to reload its configuration again.

$ service sshd reload

The next login attempt from the client should succeed as the MAC and KEX algorithms the client proposes are enabled for the ssh daemon.

Modern distributions, different log

The above explanation about interpreting the log information to find the KEX that were offered applies to conservative distributions like CentOS 6 / RHEL 6 (Red Hat Enterprise Linux) and possibly Debian. But what about modern distributions? Modern distributions like Ubuntu and possibly more recent versions of CentOS and RHEL use a more up-to-date version of OpenSSH. At the time of writing Ubuntu uses OpenSSH 7.2 where the logging is more self explanatory.

sshd[3685]: debug2: local server KEXINIT proposal [preauth]
sshd[3685]: debug2: KEX algorithms: ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256 [preauth]
sshd[3685]: debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
sshd[3685]: debug2: ciphers ctos: aes256-ctr,aes192-ctr,aes128-ctr [preauth]
sshd[3685]: debug2: ciphers stoc: aes256-ctr,aes192-ctr,aes128-ctr [preauth]
sshd[3685]: debug2: MACs ctos: hmac-sha2-512,hmac-sha2-256 [preauth]
sshd[3685]: debug2: MACs stoc: hmac-sha2-512,hmac-sha2-256 [preauth]
sshd[3685]: debug2: compression ctos: none,zlib@openssh.com [preauth]
sshd[3685]: debug2: compression stoc: none,zlib@openssh.com [preauth]
sshd[3685]: debug2: languages ctos:  [preauth]
sshd[3685]: debug2: languages stoc:  [preauth]
sshd[3685]: debug2: first_kex_follows 0  [preauth]
sshd[3685]: debug2: reserved 0  [preauth]
sshd[3685]: debug2: peer client KEXINIT proposal [preauth]
sshd[3685]: debug2: KEX algorithms: diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1 [preauth]
sshd[3685]: debug2: host key algorithms: ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-rsa-cert-v00@openssh.com,ssh-dss-cert-v00@openssh.com,ssh-rsa,ssh-dss [preauth]
sshd[3685]: debug2: ciphers ctos: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
sshd[3685]: debug2: ciphers stoc: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
sshd[3685]: debug2: MACs ctos: hmac-sha2-512 [preauth]
sshd[3685]: debug2: MACs stoc: hmac-sha2-512 [preauth]
sshd[3685]: debug2: compression ctos: none,zlib@openssh.com,zlib [preauth]
sshd[3685]: debug2: compression stoc: none,zlib@openssh.com,zlib [preauth]
sshd[3685]: debug2: languages ctos:  [preauth]
sshd[3685]: debug2: languages stoc:  [preauth]
sshd[3685]: debug2: first_kex_follows 0  [preauth]
sshd[3685]: debug2: reserved 0  [preauth]

The above example shows that  instead of the “kex_parse_kexinit” log lines, the log identifies the offered algorithms. This makes it much easier to identify the MAC, KEX and ciphers offered from both sides. There is even a line between the blocks identifying the origin of the offer.

sshd[3685]: debug2: local server KEXINIT proposal [preauth]
...
sshd[3685]: debug2: peer client KEXINIT proposal [preauth]

This way, guessing and digging in the source to understand the log is not needed any more. Sady not all distributions use the newer version of OpenSSH. With CentOS 6, OpenSSH 5.3 is still the latest, patched version available in the default repositories.


Read more of my posts on my blog at https://blog.tinned-software.net/.

This entry was posted in Linux Administration, Security and tagged , , , , . Bookmark the permalink.