Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

user resolution fails inconsistently #1666

Closed
jaymzh opened this issue Sep 22, 2020 · 12 comments
Closed

user resolution fails inconsistently #1666

jaymzh opened this issue Sep 22, 2020 · 12 comments
Labels
Resolution - Answered

Comments

@jaymzh
Copy link

jaymzh commented Sep 22, 2020 •
edited

Troubleshooting steps

"OpenSSH for Windows" version

PS C:\Users\phil> ((Get-Item (Get-Command sshd).Source).VersionInfo.FileVersion)     
8.0.0.0

Server OperatingSystem
Windows 10 Pro

Client OperatingSystem
Ubuntu 18.0.4

What is failing
When sshing to the server, about half the time the user fails to resolve. It's worth noting the user (all users) are local.

Trying the same command 2 or 3 times will succeed, but it fails several times with what the server sees as:

debug2: userauth_pubkey: disabled because of invalid user [preauth]

Expected output

debug2: languages stoc:  [preauth]
debug2: first_kex_follows 0  [preauth]
debug2: reserved 0  [preauth]
debug1: kex: algorithm: curve25519-sha256 [preauth]
debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug3: receive packet: type 30 [preauth]
debug3: mm_key_sign entering [preauth]
debug3: mm_request_send entering: type 6 [preauth]
debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth]
debug3: mm_request_receive_expect entering: type 7 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 6
debug3: mm_answer_sign
debug3: mm_answer_sign: hostkey proof signature 00000209D171BF00(100)
debug3: mm_request_send entering: type 7
debug2: monitor_read: 6 used once, disabling now
debug3: send packet: type 31 [preauth]
debug3: send packet: type 21 [preauth]
debug2: set_newkeys: mode 1 [preauth]
debug1: rekey after 134217728 blocks [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug3: send packet: type 7 [preauth]
debug3: receive packet: type 21 [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug2: set_newkeys: mode 0 [preauth]
debug1: rekey after 134217728 blocks [preauth]
debug1: KEX done [preauth]
debug3: receive packet: type 5 [preauth]
debug3: send packet: type 6 [preauth]
debug3: receive packet: type 50 [preauth]
debug1: userauth-request for user phil service ssh-connection method none [preauth]  
debug1: attempt 0 failures 0 [preauth]
debug3: mm_getpwnamallow entering [preauth]
debug3: mm_request_send entering: type 8 [preauth]
debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
debug3: mm_request_receive_expect entering: type 9 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 8
debug3: mm_answer_pwnamallow
debug2: parse_server_config: config reprocess config len 495
debug3: checking match for ...
debug3: get_user_token - i am running as phil, returning process token
debug1: user phil matched group ...
debug3: match found
<snipping checking other groups>
debug3: reprocess config:24 setting AllowUsers *
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 9
debug2: monitor_read: 8 used once, disabling now
debug2: input_userauth_request: setting up authctxt for phil [preauth]
debug3: mm_inform_authserv entering [preauth]
debug3: mm_request_send entering: type 4 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
debug3: send packet: type 51 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, style=
debug2: monitor_read: 4 used once, disabling now
debug3: receive packet: type 50 [preauth]
debug1: userauth-request for user phil service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:Wfv2sdqXaeCTNHt73FEM/dMCAuTthFVTa37sQjwa2BU [preauth]
debug3: mm_key_allowed entering [preauth]
debug3: mm_request_send entering: type 22 [preauth]
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
debug3: mm_request_receive_expect entering: type 23 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 22
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 00000209D171C050
debug1: trying public key file C:\\Users\\phil\\.ssh/authorized_keys
debug1: C:\\Users\\phil\\.ssh/authorized_keys:3: matching key found: RSA SHA256:Wfv2sdqXaeCTNHt73FEM/dMCAuTthFVTa37sQjwa2BU
debug1: C:\\Users\\phil\\.ssh/authorized_keys:3: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Accepted key RSA SHA256:Wfv2sdqXaeCTNHt73FEM/dMCAuTthFVTa37sQjwa2BU found at C:\\Users\\phil\\.ssh/authorized_keys:3
debug3: mm_answer_keyallowed: publickey authentication test: RSA key is allowed      
debug3: mm_request_send entering: type 23
debug3: send packet: type 60 [preauth]
...

I'm stopping it here because the failure doesn't get half that far, but can provide more.

Actual output

debug2: languages stoc:  [preauth]
debug2: first_kex_follows 0  [preauth]
debug2: reserved 0  [preauth]
debug1: kex: algorithm: curve25519-sha256 [preauth]
debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug3: receive packet: type 30 [preauth]
debug3: mm_key_sign entering [preauth]
debug2: monitor_read: 8 used once, disabling now
debug3: mm_inform_authserv entering [preauth]
debug3: mm_request_send entering: type 4 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
debug3: send packet: type 51 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, style=
debug2: monitor_read: 4 used once, disabling now
debug3: receive packet: type 50 [preauth]
debug1: userauth-request for user phil service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:Wfv2sdqXaeCTNHt73FEM/dMCAuTthFVTa37sQjwa2BU [preauth]
debug2: userauth_pubkey: disabled because of invalid user [preauth]
debug2: userauth_pubkey: authenticated 0 pkalg rsa-sha2-512 [preauth]
debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
debug3: send packet: type 51 [preauth]

If I then put in a password (even though key auth usually works) it will fail, and I get this additional output

debug3: receive packet: type 50 [preauth]
debug1: userauth-request for user phil service ssh-connection method password [preauth]
debug1: attempt 2 failures 1 [preauth]
debug2: input_userauth_request: try method password [preauth]
debug3: mm_auth_password entering [preauth]
debug3: mm_request_send entering: type 12 [preauth]
debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
debug3: mm_request_receive_expect entering: type 13 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 12
debug1: Windows authentication failed for user: NOUSER domain: . error: 1326
debug3: mm_answer_authpassword: sending result 0
debug3: mm_request_send entering: type 13
Failed password for invalid user phil from 10.128.12.11 port 50936 ssh2
debug3: mm_auth_password: user not authenticated [preauth]
debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
debug3: send packet: type 51 [preauth]

If keys fail, password fails, for the same reason, "invalud user"

But it was able to map me a moment ago and again on the next try.

Other Info

The same exact setup on machines that are attached to a domain don't seem to have this issue at all. The identical setup on both win2k16 server and win10 works fine on domain-ified machines, but standalone machines with local users seem to have this issue.
@NoMoreFood
Copy link

Is the user name the same as the machine name?

@jaymzh
Copy link
Author

jaymzh commented Sep 22, 2020

No, but I saw that bug too. :)

In fact I can reproduce this with multiple users.

@NoMoreFood
Copy link

Can you try with 8.1? I feel like we normally see more output relative to name resolution. Can't remember when I added that code.

@jaymzh
Copy link
Author

jaymzh commented Sep 22, 2020

Er, I just installed the Windows Capability openssh-server and that's what I got. (I'm super new to Windows (Linux guy), so my apologize for dumb questions here.) I've been trying to keep the the most supported/tested/included paths. Is there there an option to get a newer version through Windows Capabilities, or would I need to go and build my own to try out 8.1?

@NoMoreFood
Copy link

Installation instructions are here: https://github.com/PowerShell/Win32-OpenSSH/wiki/Install-Win32-OpenSSH

@jaymzh
Copy link
Author

jaymzh commented Sep 23, 2020 •
edited

Will do.

In the meantime, I think I have more data. It's not domain-vs-not-domain. It seems to be Windows 10 vs other things. I can repro this on a machine joined to the domain that has an older version of openssh (7.7.2.3).

But what's weird is I actually see MORE logs around resolving the user:

debug1: user \001\002 matched group list <somegroup> at line 19
debug1: get_passwd: LookupAccountName() failed: 1332.
debug1: Can't match group at line 21 because user n does not exist
debug1: get_passwd: LookupAccountName() failed: 1332.
debug1: Can't match group at line 23 because user n does not exist
debug1: userauth-request for user phil service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:Wfv2sdqXaeCTNHt73FEM/dMCAuTthFVTa37sQjwa2BU [preauth]

EDIT TO ADD: Here's what happens when I do debug3, it somehow does NOT print those LookupACcountName logs...

debug3: checking match for 'group <somegroup>' user corp\\phil host 10.5.80.126 addr 10.5.80.126 laddr 10.100.30.69 lport 22
debug3: get_user_token - i am running as corp\\phil, returning process token
debug1: user n matched group list <somegroup> at line 19
debug3: match found
debug3: reprocess config:20 setting AllowUsers *
<moregroupstuff>
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 0
debug3: mm_request_send entering: type 9
debug2: monitor_read: 8 used once, disabling now
debug3: mm_inform_authserv entering [preauth]
debug3: mm_request_send entering: type 4 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
debug3: send packet: type 51 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, style=
debug2: monitor_read: 4 used once, disabling now
debug3: receive packet: type 50 [preauth]
debug1: userauth-request for user phil service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:Wfv2sdqXaeCTNHt73FEM/dMCAuTthFVTa37sQjwa2BU [preauth]
debug2: userauth_pubkey: disabled because of invalid user [preauth]
debug2: userauth_pubkey: authenticated 0 pkalg rsa-sha2-512 [preauth]

weird...

@jaymzh
Copy link
Author

jaymzh commented Sep 23, 2020

8.1.0-p1 beta seems to reliably map the user well....

@jaymzh
Copy link
Author

jaymzh commented Sep 23, 2020

Turns out 8.0.0.1 from chocolately also seems to work well.

Just not the one from WindowsCapability.

@jaymzh
Copy link
Author

jaymzh commented Sep 23, 2020

I went back and forth between these 3 versions repeatedly, and it's consistent. The WindowsCapability version fails to resolve users quite often, but the chocolatey version and the latest build from GH both work reliably.

@jaymzh
Copy link
Author

jaymzh commented Sep 23, 2020

@bagajjal / @NoMoreFood - I don't mind closing this - as a developer, I understand the box is clearly fixed in modern versions of the code, but out of curiousity, do you know what the process/schedule is for getting a newer version of SSH into the WindowsCapability ... repo, for lack of a better term?

@bagajjal
Copy link
Collaborator

bagajjal commented Sep 23, 2020 •
edited

The new windows update coming next month will have latest github version binaries.
Windows update automatically updates your existing openssh binaries.

@jaymzh
Copy link
Author

jaymzh commented Sep 23, 2020

awesome, thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Resolution - Answered
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@jaymzh @NoMoreFood @bagajjal