I have set up OpenSSH 7.7 on Windows Server 2019. The box is caught up on updates as of this writing. Yesterday at the end of the day I tested connecting to the box using SFTP, using both an admin account and a restricted account created for use by a vendor, and both were able to connect and transfer files.
This morning, I tried to SFTP in, and both logins were rejected with an authentication error. The same thing happens if I try to ssh from the command line. The sshd_log entries simply say
3416 2021-08-18 10:25:08.957 Connection from XX.XX.XX.XX port 48119 on 172.31.49.52 port 22
3416 2021-08-18 10:25:10.754 Failed password for invalid user don-admin from XX.XX.XX.XX port 48119 ssh2
3416 2021-08-18 10:25:10.832 Connection closed by invalid user don-admin XX.XX.XX.XX port 48119 [preauth]
(The admin account is the same as the one I'm using to RDP into the box, by the way, so I'm sure it's not that the account has accidentally been changed or disabled.) I tried restarting the OpenSSH SSH Server and OpenSSH Authentication Agent services, to no effect.
Certainly I did not change anything overnight. I checked if there had been any automatic updates overnight, and there were not, and automatic updating is disabled, as I intended. This box is not yet in production and as far as I can see in the Security event log, no other human user logged on between my own connections.
Then, about 50 minutes later, without me having made any change at all, the sshd_log entries changed to this for some, but not all, SFTP attempts:
4628 2021-08-18 10:53:54.007 Connection from XX.XX.XX.XX port 34996 on 172.31.49.52 port 22
4628 2021-08-18 10:53:55.538 Failed publickey for sftpuser from XX.XX.XX.XX port 34996 ssh2: ED25519 SHA256:xxxxxxxxxxxxxxxx
4628 2021-08-18 10:53:55.694 Accepted password for sftpuser from XX.XX.XX.XX port 34996 ssh2
4628 2021-08-18 10:53:55.726 User child is on pid 3612
2860 2021-08-18 10:54:01.398 Connection from XX.XX.XX.XX port 43896 on 172.31.49.52 port 22
2860 2021-08-18 10:54:01.960 Failed password for invalid user sftpuser from XX.XX.XX.XX port 43896 ssh2
2860 2021-08-18 10:54:02.038 Connection closed by invalid user sftpuser XX.XX.XX.XX port 43896 [preauth]
Then, about 25 minutes after that, without me having made any change at all, everything SFTP started working normally again. This same sequence happened yesterday morning, but since I was still tweaking the configuration at the time I assumed that was the cause; but now I'm thinking it was this same thing. It's almost like OpenSSH needs to wake up and warm up in the morning before it works right.
Since the SFTP site needs to be available to our vendor for daily use once we go into production, I really need to figure out what's going on and how to smooth it out, but I'm entirely without a clue what else to look at here. Can anyone suggest an explanation, or at least what to try next to diagnose this?
[Update]
A couple hours later, without me having made any change at all, connections stopped working again and attempts are again met with the authentication error.
[Update]
Here are the DEBUG-level log entries for a failed attempt:
2924 2021-08-18 16:57:59.653 debug1: inetd sockets after dupping: 3, 3
2924 2021-08-18 16:57:59.653 Connection from 97.115.151.126 port 47632 on 172.31.49.52 port 22
2924 2021-08-18 16:57:59.653 debug1: Client protocol version 2.0; client software version FileZilla_3.55.1
2924 2021-08-18 16:57:59.653 debug1: no match: FileZilla_3.55.1
2924 2021-08-18 16:57:59.653 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_7.7
2924 2021-08-18 16:57:59.685 debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
2924 2021-08-18 16:57:59.685 debug1: SSH2_MSG_KEXINIT sent [preauth]
2924 2021-08-18 16:57:59.731 debug1: SSH2_MSG_KEXINIT received [preauth]
2924 2021-08-18 16:57:59.731 debug1: kex: algorithm: curve25519-sha256 [preauth]
2924 2021-08-18 16:57:59.731 debug1: kex: host key algorithm: ssh-ed25519 [preauth]
2924 2021-08-18 16:57:59.731 debug1: kex: client->server cipher: [email protected] MAC: <implicit> compression: none [preauth]
2924 2021-08-18 16:57:59.731 debug1: kex: server->client cipher: [email protected] MAC: <implicit> compression: none [preauth]
2924 2021-08-18 16:57:59.731 debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
2924 2021-08-18 16:57:59.809 debug1: rekey after 4294967296 blocks [preauth]
2924 2021-08-18 16:57:59.809 debug1: SSH2_MSG_NEWKEYS sent [preauth]
2924 2021-08-18 16:57:59.809 debug1: expecting SSH2_MSG_NEWKEYS [preauth]
2924 2021-08-18 16:57:59.903 debug1: SSH2_MSG_NEWKEYS received [preauth]
2924 2021-08-18 16:57:59.903 debug1: rekey after 4294967296 blocks [preauth]
2924 2021-08-18 16:57:59.903 debug1: KEX done [preauth]
2924 2021-08-18 16:57:59.981 debug1: userauth-request for user wisdomwhere-sftp service ssh-connection method none [preauth]
2924 2021-08-18 16:57:59.981 debug1: attempt 0 failures 0 [preauth]
2924 2021-08-18 16:57:59.981 debug1: user n matched group list solutionwhere at line 86
2924 2021-08-18 16:57:59.981 debug1: get_passwd: LookupAccountName() failed: 1332.
2924 2021-08-18 16:57:59.981 debug1: Can't match group at line 93 because user n does not exist
2924 2021-08-18 16:58:00.059 debug1: userauth-request for user wisdomwhere-sftp service ssh-connection method publickey [preauth]
2924 2021-08-18 16:58:00.059 debug1: attempt 1 failures 0 [preauth]
2924 2021-08-18 16:58:00.059 debug1: userauth_pubkey: test pkalg ssh-ed25519 pkblob ED25519 SHA256:ZiwK/RCeTj8jshoMs22PvyckMLSGZE4EEZuNhhyIkog [preauth]
2924 2021-08-18 16:58:00.138 debug1: userauth-request for user wisdomwhere-sftp service ssh-connection method keyboard-interactive [preauth]
2924 2021-08-18 16:58:00.138 debug1: attempt 2 failures 1 [preauth]
2924 2021-08-18 16:58:00.138 debug1: keyboard-interactive devs [preauth]
2924 2021-08-18 16:58:00.138 debug1: auth2_challenge: user=wisdomwhere-sftp devs= [preauth]
2924 2021-08-18 16:58:00.138 debug1: kbdint_alloc: devices '' [preauth]
2924 2021-08-18 16:58:00.231 debug1: userauth-request for user wisdomwhere-sftp service ssh-connection method password [preauth]
2924 2021-08-18 16:58:00.231 debug1: attempt 3 failures 2 [preauth]
2924 2021-08-18 16:58:00.231 debug1: Windows authentication failed for user: NOUSER domain: . error: 1326
2924 2021-08-18 16:58:00.231 Failed password for invalid user wisdomwhere-sftp from 97.115.151.126 port 47632 ssh2
2924 2021-08-18 16:58:00.309 Connection closed by invalid user wisdomwhere-sftp 97.115.151.126 port 47632 [preauth]
2924 2021-08-18 16:58:00.309 debug1: do_cleanup [preauth]
2924 2021-08-18 16:58:00.309 debug1: monitor_read_log: child log fd closed
2924 2021-08-18 16:58:00.309 debug1: do_cleanup
2924 2021-08-18 16:58:00.309 debug1: Killing privsep child 3476
And here are the DEBUG-level log entries for a successful connection a few minutes later (keeping in mind that there were no configuration changes on either end between the two attempts):
3188 2021-08-18 17:15:43.726 debug1: inetd sockets after dupping: 3, 3
3188 2021-08-18 17:15:43.726 Connection from 97.115.151.126 port 43761 on 172.31.49.52 port 22
3188 2021-08-18 17:15:43.726 debug1: Client protocol version 2.0; client software version FileZilla_3.55.1
3188 2021-08-18 17:15:43.726 debug1: no match: FileZilla_3.55.1
3188 2021-08-18 17:15:43.726 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_7.7
3188 2021-08-18 17:15:43.758 debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
3188 2021-08-18 17:15:43.758 debug1: SSH2_MSG_KEXINIT sent [preauth]
3188 2021-08-18 17:15:43.804 debug1: SSH2_MSG_KEXINIT received [preauth]
3188 2021-08-18 17:15:43.804 debug1: kex: algorithm: curve25519-sha256 [preauth]
3188 2021-08-18 17:15:43.804 debug1: kex: host key algorithm: ssh-ed25519 [preauth]
3188 2021-08-18 17:15:43.804 debug1: kex: client->server cipher: [email protected] MAC: <implicit> compression: none [preauth]
3188 2021-08-18 17:15:43.804 debug1: kex: server->client cipher: [email protected] MAC: <implicit> compression: none [preauth]
3188 2021-08-18 17:15:43.804 debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
3188 2021-08-18 17:15:43.883 debug1: rekey after 4294967296 blocks [preauth]
3188 2021-08-18 17:15:43.883 debug1: SSH2_MSG_NEWKEYS sent [preauth]
3188 2021-08-18 17:15:43.883 debug1: expecting SSH2_MSG_NEWKEYS [preauth]
3188 2021-08-18 17:15:43.976 debug1: SSH2_MSG_NEWKEYS received [preauth]
3188 2021-08-18 17:15:43.976 debug1: rekey after 4294967296 blocks [preauth]
3188 2021-08-18 17:15:43.976 debug1: KEX done [preauth]
3188 2021-08-18 17:15:44.054 debug1: userauth-request for user wisdomwhere-sftp service ssh-connection method none [preauth]
3188 2021-08-18 17:15:44.054 debug1: attempt 0 failures 0 [preauth]
3188 2021-08-18 17:15:44.054 debug1: user wisdomwhere-sftp matched group list solutionwhere at line 86
3188 2021-08-18 17:15:44.054 debug1: user wisdomwhere-sftp does not match group list administrators at line 93
3188 2021-08-18 17:15:44.133 debug1: userauth-request for user wisdomwhere-sftp service ssh-connection method publickey [preauth]
3188 2021-08-18 17:15:44.133 debug1: attempt 1 failures 0 [preauth]
3188 2021-08-18 17:15:44.133 debug1: userauth_pubkey: test pkalg ssh-ed25519 pkblob ED25519 SHA256:ZiwK/RCeTj8jshoMs22PvyckMLSGZE4EEZuNhhyIkog [preauth]
3188 2021-08-18 17:15:44.133 debug1: trying public key file C:\\Users\\wisdomwhere-sftp\\.ssh/authorized_keys
3188 2021-08-18 17:15:44.133 debug1: Could not open authorized keys 'C:\\Users\\wisdomwhere-sftp\\.ssh/authorized_keys': No such file or directory
3188 2021-08-18 17:15:44.133 Failed publickey for wisdomwhere-sftp from 97.115.151.126 port 43761 ssh2: ED25519 SHA256:ZiwK/RCeTj8jshoMs22PvyckMLSGZE4EEZuNhhyIkog
3188 2021-08-18 17:15:44.211 debug1: userauth-request for user wisdomwhere-sftp service ssh-connection method keyboard-interactive [preauth]
3188 2021-08-18 17:15:44.211 debug1: attempt 2 failures 1 [preauth]
3188 2021-08-18 17:15:44.211 debug1: keyboard-interactive devs [preauth]
3188 2021-08-18 17:15:44.211 debug1: auth2_challenge: user=wisdomwhere-sftp devs= [preauth]
3188 2021-08-18 17:15:44.211 debug1: kbdint_alloc: devices '' [preauth]
3188 2021-08-18 17:15:44.289 debug1: userauth-request for user wisdomwhere-sftp service ssh-connection method password [preauth]
3188 2021-08-18 17:15:44.289 debug1: attempt 3 failures 2 [preauth]
3188 2021-08-18 17:15:44.304 Accepted password for wisdomwhere-sftp from 97.115.151.126 port 43761 ssh2
3188 2021-08-18 17:15:44.304 debug1: monitor_child_preauth: wisdomwhere-sftp has been authenticated by privileged process
3188 2021-08-18 17:15:44.304 debug1: monitor_read_log: child log fd closed
3188 2021-08-18 17:15:44.320 User child is on pid 5716
Line 22 is where they diverge...The failed attempt stops referring to user wisdomwhere-sftp and starts referring to user n. What could be the cause of that?
