Strange problem connecting to a buster server with PuTTY using public key

[Bernhard Fröhlich]

Hi there,

I have a quite strange problem here when trying to connect to a newly installed Debian buster server (OpenSSH_7.9p1 Debian-10+deb10u2, OpenSSL 1.1.1d 10 Sep 2019) with PuTTY 0.74 using public key authentication.

The key is cached in a Pageant key vault, though I have the same behaviour without.
When trying to connect directly I get told that "Server refused our key". When I continue by entering the password I get access. The access.log shows these lines:

Mar 25 10:04:10 coturn sshd[5486]: debug1: userauth-request for user ted service ssh-connection method none [preauth]
Mar 25 10:04:10 coturn sshd[5486]: debug1: attempt 0 failures 0 [preauth]
Mar 25 10:04:10 coturn sshd[5486]: debug1: PAM: initializing for "ted"
Mar 25 10:04:10 coturn sshd[5486]: debug1: PAM: setting PAM_RHOST to "...:7f6e"
Mar 25 10:04:10 coturn sshd[5486]: debug1: PAM: setting PAM_TTY to "ssh"
Mar 25 10:04:10 coturn sshd[5486]: debug1: userauth-request for user ted service ssh-connection method publickey [preauth]
Mar 25 10:04:10 coturn sshd[5486]: debug1: attempt 1 failures 0 [preauth]
Mar 25 10:04:10 coturn sshd[5486]: debug1: userauth_pubkey: test pkalg ssh-rsa pkblob RSA SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw [preauth]
Mar 25 10:04:10 coturn sshd[5486]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Mar 25 10:04:10 coturn sshd[5486]: debug1: trying public key file /home/ted/.ssh/authorized_keys
Mar 25 10:04:10 coturn sshd[5486]: debug1: fd 4 clearing O_NONBLOCK
Mar 25 10:04:10 coturn sshd[5486]: debug1: restore_uid: 0/0
Mar 25 10:04:10 coturn sshd[5486]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Mar 25 10:04:10 coturn sshd[5486]: debug1: trying public key file /home/ted/.ssh/authorized_keys2
Mar 25 10:04:10 coturn sshd[5486]: debug1: Could not open authorized keys '/home/ted/.ssh/authorized_keys2': No such file or directory
Mar 25 10:04:10 coturn sshd[5486]: debug1: restore_uid: 0/0
Mar 25 10:04:10 coturn sshd[5486]: Failed publickey for ted from 2001:a61:1163:c401:583a:4308:2ac1:7f6e port 49838 ssh2: RSA SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw

OK, of course the first thought is that the key is not correct in authorized_keys, but then I tried to connect to another server (an old debian stretch, OpenSSH_7.9p1 Debian-10+deb10u2, OpenSSL 1.1.1d 10 Sep 2019) with agent forwarding allowed, and connecting from that server to the new buster server. This worked fine and gave the following log lines:

Mar 25 10:33:44 coturn sshd[5600]: debug1: userauth-request for user ted service ssh-connection method none [preauth]
Mar 25 10:33:44 coturn sshd[5600]: debug1: attempt 0 failures 0 [preauth]
Mar 25 10:33:44 coturn sshd[5600]: debug1: PAM: initializing for "ted"
Mar 25 10:33:44 coturn sshd[5600]: debug1: PAM: setting PAM_RHOST to "...:3b11"
Mar 25 10:33:44 coturn sshd[5600]: debug1: PAM: setting PAM_TTY to "ssh"
Mar 25 10:33:44 coturn sshd[5600]: debug1: userauth-request for user ted service ssh-connection method publickey [preauth]
Mar 25 10:33:44 coturn sshd[5600]: debug1: attempt 1 failures 0 [preauth]
Mar 25 10:33:44 coturn sshd[5600]: debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw [preauth]
Mar 25 10:33:44 coturn sshd[5600]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Mar 25 10:33:44 coturn sshd[5600]: debug1: trying public key file /home/ted/.ssh/authorized_keys
Mar 25 10:33:44 coturn sshd[5600]: debug1: fd 4 clearing O_NONBLOCK
Mar 25 10:33:44 coturn sshd[5600]: debug1: /home/ted/.ssh/authorized_keys:9: matching key found: RSA SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw
Mar 25 10:33:44 coturn sshd[5600]: debug1: /home/ted/.ssh/authorized_keys:9: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Mar 25 10:33:44 coturn sshd[5600]: Accepted key RSA SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw found at /home/ted/.ssh/authorized_keys:9

Now, can anyone explain this to me? I always thought that the key hash (SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw) decides whether the line in authorized_keys is found or not. Am I wrong somewhere?

Note that I had the same behaviour on another computer. While looking for the reason I was playing around, changing some things here and there, and suddenly it worked (and worked since then). Sadly I'm not sure about what I changed directly before it worked, probably it was something in the PuTTY configuration...
Also I'm not sure whether some settings are cached in PuTTY, so maybe it would not even the latest change...

Any hints appreceated...
Kind regards
Ted

[Richard Kettlewell]

Bernhard Fröhlich <bern...@cacert.org> writes:
> Mar 25 10:04:10 coturn sshd[5486]: debug1: trying public key file
> /home/ted/.ssh/authorized_keys

The public key needs to be in this file, and apparently isn’t. Either
it’s completely missing, or you have the wrong syntax, or a typo, or
something like that. Without visibility of the file’s contents it’s
impossible to say more.

[...]

> Now, can anyone explain this to me? I always thought that the key hash
> (SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw) decides whether
> the line in authorized_keys is found or not. Am I wrong somewhere?

authorized_keys contains public key material, not key hashes.

--
https://www.greenend.org.uk/rjk/

[Bernhard Fröhlich]

Hi Richard!

Richard Kettlewell schrieb am Donnerstag, 25. März 2021 um 14:53:03 UTC+1:

> Bernhard Fröhlich writes:
> > Mar 25 10:04:10 coturn sshd[5486]: debug1: trying public key file
> > /home/ted/.ssh/authorized_keys
> The public key needs to be in this file, and apparently isn’t. Either
> it’s completely missing, or you have the wrong syntax, or a typo, or
> something like that. Without visibility of the file’s contents it’s
> impossible to say more.

The authorized_keys file was not changed between the two log excerpts!

Is there any way to find out why during the first try the key was not found while during the second try it was?

> > Now, can anyone explain this to me? I always thought that the key hash
> > (SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw) decides whether
> > the line in authorized_keys is found or not. Am I wrong somewhere?
> authorized_keys contains public key material, not key hashes.

Sorry, I obviously used the wrong term.

Nevertheless this hash can be calculated from the public key material contained in the authorized_keys file (at least using "base64 -d | openssl dgst -sha256 -binary | base64" produces an extremely similar string). So I naively assumed that sshd does it that way, and that this was the reason why this value is written to the debug log...

So it would be most interesting how sshd decides that a line from authorized_keys matches a key offered by the client during the handshake...


In the meantime I once more got the PuTTY configuration working by creating a new configuration (compared to just changing the target host name in an existing configuration). The auth.log on the server is exactly the same (verified by diff) as in the failed connection attempt till it comes to the "matching key found" line...

So it looks like the cause of the problem lies on the client side and the auth.log on the server is not helpful to locate this problem, at least not in this DebugLevel setting...

Sorry for having bothered you, and thanks for your answer!


Nevertheless I'd really be curious about the real cause. I indeed could not make out suspicious differences in the PuTTY configuration after dumping the registry keys and diffing them. And I could not provoke the same error by doing the same things I did when this error occured... Maybe this only works once per client workstation or client user account?

But probably this would be something for PuTTY insiders...

Kind regards
Ted
;)

[Richard Kettlewell]

Bernhard Fröhlich <bern...@cacert.org> writes:
> Richard Kettlewell schrieb am Donnerstag, 25. März 2021 um 14:53:03 UTC+1:
>> Bernhard Fröhlich writes:
>>> Mar 25 10:04:10 coturn sshd[5486]: debug1: trying public key file
>>> /home/ted/.ssh/authorized_keys
>> The public key needs to be in this file, and apparently isn’t. Either
>> it’s completely missing, or you have the wrong syntax, or a typo, or
>> something like that. Without visibility of the file’s contents it’s
>> impossible to say more.
>
> The authorized_keys file was not changed between the two log excerpts!
>
> Is there any way to find out why during the first try the key was not
> found while during the second try it was?

Some of the diagnostics are debug messages only, so running sshd with
-d might shed some light on it.

https://github.com/openssh/openssh-portable/blob/master/auth2-pubkey.c
check_authkeys_file and check_authkey_line are the starting points.

> So it would be most interesting how sshd decides that a line from
> authorized_keys matches a key offered by the client during the
> handshake...

It compares the key components (which in the case of RSA means the
public exponent and public modulus) for equality.

--
https://www.greenend.org.uk/rjk/

[Simon Tatham]

Bernhard Fröhlich <bern...@cacert.org> wrote:

[in the failing case]

> Mar 25 10:04:10 coturn sshd[5486]: debug1: userauth_pubkey: test pkalg
> ssh-rsa pkblob RSA SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw

[in the working case]

> Mar 25 10:33:44 coturn sshd[5600]: debug1: userauth_pubkey: test pkalg
> rsa-sha2-512 pkblob RSA
> SHA256:Awr0ikVD79MmKnd1vxIsbvjg0c4/NivKlZ9Rh84CAZw [preauth]

I suspect the difference is 'ssh-rsa' vs 'rsa-sha2-512'. The former is
the original definition of RSA public keys for SSH, which uses SHA-1
as the hash. The latter is a more recent one that uses SHA-512. Most
likely your server is set up to reject ssh-rsa for being old and
obsolete, and accept the newer rsa-sha2-512.

The current snapshot builds of PuTTY include support for rsa-sha2-512.
If you try a snapshot build in place of 0.74, does it help?
--
import hashlib; print((lambda p,q,g,y,r,s,m: (lambda w:(pow(g,int(hashlib.sha1(
m.encode('ascii')).hexdigest(),16)*w%q,p)*pow(y,r*w%q,p)%p)%q)(pow(s,q-2,q))==r
and m)(0xb80b5dacabab6145,0xf70027d345023,0x7643bc4018957897,0x11c2e5d9951130c9
,0xa54d9cbe4e8ab,0x746c50eaa1910, "Simon Tatham <ana...@pobox.com>" ))