sshd does not use user publickey from authorized_keys

[olafhering]

Troubleshooting steps
https://github.com/PowerShell/Win32-OpenSSH/wiki/Troubleshooting-Steps

Terminal issue? please go through wiki
https://github.com/PowerShell/Win32-OpenSSH/wiki/TTY-PTY-support-in-Windows-OpenSSH

Please answer the following

"OpenSSH for Windows" version
((Get-Item (Get-Command sshd).Source).VersionInfo.FileVersion)
8.0.0.0

Server OperatingSystem
((Get-ItemProperty "HKLM:\SOFTWARE\Microsoft\Windows nt\CurrentVersion\" -Name ProductName).ProductName)
Windows Server 2016 Datacenter

Client OperatingSystem
Leap 15.1

What is failing
ssh into Windows should not ask for a password if c:\users\username\.ssh\authorized_keys exist. But for whatever reason sshd does not seem to make an attempt to use this file.

Not sure if this issue tracker should be used as a chat system..

Actual output

8788 2019-07-24 19:45:03.245 debug3: fd 5 is not O_NONBLOCK
8788 2019-07-24 19:45:03.245 debug3: spawning "C:\\Program Files\\OpenSSH-Win64\\sshd.exe" -R
8788 2019-07-24 19:45:03.323 debug3: send_rexec_state: entering fd = 8 config len 196
8788 2019-07-24 19:45:03.323 debug3: ssh_msg_send: type 0
8788 2019-07-24 19:45:03.323 debug3: send_rexec_state: done
4448 2019-07-24 19:45:03.433 debug1: inetd sockets after dupping: 4, 4
4448 2019-07-24 19:45:03.433 Connection from 10.163.8.87 port 49360 on 10.161.8.241 port 22
4448 2019-07-24 19:45:03.433 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_8.0
4448 2019-07-24 19:45:03.433 debug1: Remote protocol version 2.0, remote software version OpenSSH_7.9
4448 2019-07-24 19:45:03.433 debug1: match: OpenSSH_7.9 pat OpenSSH* compat 0x04000000
4448 2019-07-24 19:45:03.433 debug2: fd 4 setting O_NONBLOCK
4448 2019-07-24 19:45:03.938 debug3: spawning "C:\\Program Files\\OpenSSH-Win64\\sshd.exe" -y
4448 2019-07-24 19:45:04.016 debug2: Network child is on pid 4760
4448 2019-07-24 19:45:04.016 debug3: send_rexec_state: entering fd = 6 config len 196
4448 2019-07-24 19:45:04.016 debug3: ssh_msg_send: type 0
4448 2019-07-24 19:45:04.016 debug3: send_rexec_state: done
4448 2019-07-24 19:45:04.016 debug3: ssh_msg_send: type 0
4448 2019-07-24 19:45:04.016 debug3: ssh_msg_send: type 0
4448 2019-07-24 19:45:04.016 debug3: preauth child monitor started
4448 2019-07-24 19:45:04.047 debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
4448 2019-07-24 19:45:04.047 debug3: send packet: type 20 [preauth]
4448 2019-07-24 19:45:04.047 debug1: SSH2_MSG_KEXINIT sent [preauth]
4448 2019-07-24 19:45:04.047 debug3: receive packet: type 20 [preauth]
4448 2019-07-24 19:45:04.047 debug1: SSH2_MSG_KEXINIT received [preauth]
4448 2019-07-24 19:45:04.047 debug2: local server KEXINIT proposal [preauth]
4448 2019-07-24 19:45:04.047 debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1 [preauth]
4448 2019-07-24 19:45:04.047 debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
4448 2019-07-24 19:45:04.047 debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
4448 2019-07-24 19:45:04.047 debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
4448 2019-07-24 19:45:04.047 debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
4448 2019-07-24 19:45:04.047 debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
4448 2019-07-24 19:45:04.047 debug2: compression ctos: none [preauth]
4448 2019-07-24 19:45:04.047 debug2: compression stoc: none [preauth]
4448 2019-07-24 19:45:04.047 debug2: languages ctos:  [preauth]
4448 2019-07-24 19:45:04.047 debug2: languages stoc:  [preauth]
4448 2019-07-24 19:45:04.047 debug2: first_kex_follows 0  [preauth]
4448 2019-07-24 19:45:04.047 debug2: reserved 0  [preauth]
4448 2019-07-24 19:45:04.047 debug2: peer client KEXINIT proposal [preauth]
4448 2019-07-24 19:45:04.047 debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c [preauth]
4448 2019-07-24 19:45:04.047 debug2: host key algorithms: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa [preauth]
4448 2019-07-24 19:45:04.047 debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
4448 2019-07-24 19:45:04.047 debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
4448 2019-07-24 19:45:04.047 debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
4448 2019-07-24 19:45:04.047 debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
4448 2019-07-24 19:45:04.047 debug2: compression ctos: zlib@openssh.com,zlib,none [preauth]
4448 2019-07-24 19:45:04.047 debug2: compression stoc: zlib@openssh.com,zlib,none [preauth]
4448 2019-07-24 19:45:04.047 debug2: languages ctos:  [preauth]
4448 2019-07-24 19:45:04.047 debug2: languages stoc:  [preauth]
4448 2019-07-24 19:45:04.047 debug2: first_kex_follows 0  [preauth]
4448 2019-07-24 19:45:04.047 debug2: reserved 0  [preauth]
4448 2019-07-24 19:45:04.047 debug1: kex: algorithm: curve25519-sha256 [preauth]
4448 2019-07-24 19:45:04.047 debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
4448 2019-07-24 19:45:04.047 debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
4448 2019-07-24 19:45:04.047 debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
4448 2019-07-24 19:45:04.047 debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
4448 2019-07-24 19:45:04.063 debug3: receive packet: type 30 [preauth]
4448 2019-07-24 19:45:04.078 debug3: mm_sshkey_sign entering [preauth]
4448 2019-07-24 19:45:04.078 debug3: mm_request_send entering: type 6 [preauth]
4448 2019-07-24 19:45:04.078 debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
4448 2019-07-24 19:45:04.078 debug3: mm_request_receive_expect entering: type 7 [preauth]
4448 2019-07-24 19:45:04.078 debug3: mm_request_receive entering [preauth]
4448 2019-07-24 19:45:04.078 debug3: mm_request_receive entering
4448 2019-07-24 19:45:04.078 debug3: monitor_read: checking request 6
4448 2019-07-24 19:45:04.078 debug3: mm_answer_sign
4448 2019-07-24 19:45:04.078 debug3: mm_answer_sign: hostkey proof signature 0000025D9597C370(101)
4448 2019-07-24 19:45:04.078 debug3: mm_request_send entering: type 7
4448 2019-07-24 19:45:04.078 debug2: monitor_read: 6 used once, disabling now
4448 2019-07-24 19:45:04.078 debug3: send packet: type 31 [preauth]
4448 2019-07-24 19:45:04.078 debug3: send packet: type 21 [preauth]
4448 2019-07-24 19:45:04.078 debug2: set_newkeys: mode 1 [preauth]
4448 2019-07-24 19:45:04.078 debug1: rekey out after 134217728 blocks [preauth]
4448 2019-07-24 19:45:04.078 debug1: SSH2_MSG_NEWKEYS sent [preauth]
4448 2019-07-24 19:45:04.078 debug1: expecting SSH2_MSG_NEWKEYS [preauth]
4448 2019-07-24 19:45:04.078 debug3: send packet: type 7 [preauth]
4448 2019-07-24 19:45:04.110 debug3: receive packet: type 21 [preauth]
4448 2019-07-24 19:45:04.110 debug1: SSH2_MSG_NEWKEYS received [preauth]
4448 2019-07-24 19:45:04.110 debug2: set_newkeys: mode 0 [preauth]
4448 2019-07-24 19:45:04.110 debug1: rekey in after 134217728 blocks [preauth]
4448 2019-07-24 19:45:04.110 debug1: KEX done [preauth]
4448 2019-07-24 19:45:04.188 debug3: receive packet: type 5 [preauth]
4448 2019-07-24 19:45:04.188 debug3: send packet: type 6 [preauth]
4448 2019-07-24 19:45:04.219 debug3: receive packet: type 50 [preauth]
4448 2019-07-24 19:45:04.219 debug1: userauth-request for user olh service ssh-connection method none [preauth]
4448 2019-07-24 19:45:04.219 debug1: attempt 0 failures 0 [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_getpwnamallow entering [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_request_send entering: type 8 [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_request_receive_expect entering: type 9 [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_request_receive entering [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_request_receive entering
4448 2019-07-24 19:45:04.219 debug3: monitor_read: checking request 8
4448 2019-07-24 19:45:04.219 debug3: mm_answer_pwnamallow
4448 2019-07-24 19:45:04.219 debug2: parse_server_config: config reprocess config len 196
4448 2019-07-24 19:45:04.219 debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
4448 2019-07-24 19:45:04.219 debug3: mm_request_send entering: type 9
4448 2019-07-24 19:45:04.219 debug2: monitor_read: 8 used once, disabling now
4448 2019-07-24 19:45:04.219 debug2: input_userauth_request: setting up authctxt for olh [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_inform_authserv entering [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_request_send entering: type 4 [preauth]
4448 2019-07-24 19:45:04.219 debug2: input_userauth_request: try method none [preauth]
4448 2019-07-24 19:45:04.219 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
4448 2019-07-24 19:45:04.219 debug3: ensure_minimum_time_since: elapsed 0.000ms, delaying 8.717ms (requested 8.717ms) [preauth]
4448 2019-07-24 19:45:04.219 debug3: mm_request_receive entering
4448 2019-07-24 19:45:04.219 debug3: monitor_read: checking request 4
4448 2019-07-24 19:45:04.219 debug3: mm_answer_authserv: service=ssh-connection, style=
4448 2019-07-24 19:45:04.219 debug2: monitor_read: 4 used once, disabling now
4448 2019-07-24 19:45:04.235 debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
4448 2019-07-24 19:45:04.235 debug3: send packet: type 51 [preauth]
4448 2019-07-24 19:45:04.250 debug3: receive packet: type 50 [preauth]
4448 2019-07-24 19:45:04.250 debug1: userauth-request for user olh service ssh-connection method keyboard-interactive [preauth]
4448 2019-07-24 19:45:04.250 debug1: attempt 1 failures 0 [preauth]
4448 2019-07-24 19:45:04.250 debug2: input_userauth_request: try method keyboard-interactive [preauth]
4448 2019-07-24 19:45:04.250 debug1: keyboard-interactive devs  [preauth]
4448 2019-07-24 19:45:04.250 debug1: auth2_challenge: user=olh devs= [preauth]
4448 2019-07-24 19:45:04.250 debug1: kbdint_alloc: devices '' [preauth]
4448 2019-07-24 19:45:04.250 debug2: auth2_challenge_start: devices  [preauth]
4448 2019-07-24 19:45:04.250 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
4448 2019-07-24 19:45:04.250 debug3: ensure_minimum_time_since: elapsed 0.000ms, delaying 8.717ms (requested 8.717ms) [preauth]
4448 2019-07-24 19:45:04.266 debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
4448 2019-07-24 19:45:04.266 debug3: send packet: type 51 [preauth]

My silly script to install the downloaded openssh.zip:

Expand-Archive -LiteralPath $sshd_zip -DestinationPath $Env:Programfiles
powershell.exe -ExecutionPolicy Bypass -File $sshd_inst
Set-Service sshd -StartupType Automatic 
New-NetFirewallRule -Name sshd -DisplayName 'OpenSSH Server (sshd)' -Enabled True -Direction Inbound -Protocol TCP -Action Allow -LocalPort 22
powershell.exe -ExecutionPolicy Bypass -File $sshd_fix
Start-Service sshd

[jborean93]

Have a look at #1324. The authorized_keys file for users who are in the Administrators group is not in ~/.ssh/authorized_keys. You either need to use the new config entry or edit the config to go back to this normal way of working.

[olafhering]

Both files exist, so I would expect that sshd uses at least one of them.

[olafhering]

If I reenable the Group match it is apparently used. But the publickey method is not used, only keyboard-interactive.

[olafhering]

It happens to work on another WS2016 host, which was freshly installed a few days ago, with ~user/.ssh/authorized_keys

[maertendMSFT]

Can you please provide the complete SSHD log? The one posted is not complete

[olafhering]

The disk died a few weeks ago, this specific setup does not exist anymore.
Unclear what is missing in the log provided above.

[bagajjal]

@olafhering - There is no error message or indication about public key read from authorized_keys.

copied the last few lines of sshd.log shared above,

4448 2019-07-24 19:45:04.250 debug1: userauth-request for user olh service ssh-connection method keyboard-interactive [preauth]
4448 2019-07-24 19:45:04.250 debug1: attempt 1 failures 0 [preauth]
4448 2019-07-24 19:45:04.250 debug2: input_userauth_request: try method keyboard-interactive [preauth]
4448 2019-07-24 19:45:04.250 debug1: keyboard-interactive devs [preauth]
4448 2019-07-24 19:45:04.250 debug1: auth2_challenge: user=olh devs= [preauth]
4448 2019-07-24 19:45:04.250 debug1: kbdint_alloc: devices '' [preauth]
4448 2019-07-24 19:45:04.250 debug2: auth2_challenge_start: devices [preauth]
4448 2019-07-24 19:45:04.250 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
4448 2019-07-24 19:45:04.250 debug3: ensure_minimum_time_since: elapsed 0.000ms, delaying 8.717ms (requested 8.717ms) [preauth]
4448 2019-07-24 19:45:04.266 debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
4448 2019-07-24 19:45:04.266 debug3: send packet: type 51 [preauth]

Closing this issue as it's not reproducible anymore.

[olafhering]

Two fresh systems, WS2016 and WS2019, installed yesterday. Login worked yesterday on both.
Today systems got moved to the final rack. password-less ssh login stopped working.

So I think the bug I saw and reported earlier does in fact exist...