#1035754 openssh-server: PermitEmptyPasswords=yes causes login to take 2-4s by enabling PAM password check

Package:
openssh-server
Source:
openssh-server
Description:
secure shell (SSH) server, for secure access from remote machines
Submitter:
Zachary Vance
Date:
2023-05-08 18:03:07 UTC
Severity:
normal
#1035754#5
Date:
2023-05-08 17:59:56 UTC
From:
To:
Dear Maintainer,

* What led up to the situation?
    Enable the following options in sshd_config:

    PermitEmptyPasswords yes
    PasswordAuthentication no # Also the default. Confirming order doesn't matter.

    Log in using an ssh key.

* What was the outcome of this action?
    This takes 2000-4000ms on my server. I suspect the slowness is from PAM checking passwords somehow.

    The relevant log lines from the server:

        May 08 13:53:48 germinate sshd[2561718]: debug1: Forked child 3847417.
        May 08 13:53:48 germinate sshd[3847417]: debug1: Set /proc/self/oom_score_adj to 0
        May 08 13:53:48 germinate sshd[3847417]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
        May 08 13:53:48 germinate sshd[3847417]: debug1: inetd sockets after dupping: 4, 4
        May 08 13:53:48 germinate sshd[3847417]: Connection from 192.168.1.100 port 54350 on 192.168.1.17 port 22 rdomain ""
        May 08 13:53:48 germinate sshd[3847417]: debug1: Local version string SSH-2.0-OpenSSH_8.4p1 Debian-5+deb11u1
        May 08 13:53:48 germinate sshd[3847417]: debug1: Remote protocol version 2.0, remote software version OpenSSH_9.3
        May 08 13:53:48 germinate sshd[3847417]: debug1: match: OpenSSH_9.3 pat OpenSSH* compat 0x04000000
        May 08 13:53:48 germinate sshd[3847417]: debug1: permanently_set_uid: 106/65534 [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: SSH2_MSG_KEXINIT sent [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: SSH2_MSG_KEXINIT received [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: kex: algorithm: curve25519-sha256 [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: rekey out after 134217728 blocks [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: Sending SSH2_MSG_EXT_INFO [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: SSH2_MSG_NEWKEYS received [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: rekey in after 134217728 blocks [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: KEX done [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: userauth-request for user zachary service ssh-connection method none [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: attempt 0 failures 0 [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: user zachary matched 'User zachary' at line 133
        May 08 13:53:48 germinate sshd[3847417]: debug1: PAM: initializing for "zachary"
        May 08 13:53:48 germinate sshd[3847417]: debug1: PAM: setting PAM_RHOST to "192.168.1.100"
        May 08 13:53:48 germinate sshd[3847417]: debug1: PAM: setting PAM_TTY to "ssh"
        May 08 13:53:48 germinate sshd[3847417]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=192.168.1.100  user=zachary
        May 08 13:53:50 germinate sshd[3847417]: debug1: PAM: password authentication failed for zachary: Authentication failure
        May 08 13:53:50 germinate sshd[3847417]: Failed none for zachary from 192.168.1.100 port 54350 ssh2
        May 08 13:53:51 germinate sshd[3847417]: debug1: userauth-request for user zachary service ssh-connection method publickey [preauth]
        May 08 13:53:51 germinate sshd[3847417]: debug1: attempt 1 failures 0 [preauth]
        May 08 13:53:51 germinate sshd[3847417]: debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:Zt8jjAh4Z8iQ1+219IV7eNmSnQ154QbBoJ947jVEDDk [preauth]
        May 08 13:53:51 germinate sshd[3847417]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
        May 08 13:53:51 germinate sshd[3847417]: debug1: trying public key file /home/zachary/.ssh/authorized_keys
        May 08 13:53:51 germinate sshd[3847417]: debug1: fd 5 clearing O_NONBLOCK
        May 08 13:53:51 germinate sshd[3847417]: debug1: /home/zachary/.ssh/authorized_keys:1: matching key found: RSA SHA256:Zt8jjAh4Z8iQ1+219IV7eNmSnQ154QbBoJ947jVEDDk
        May 08 13:53:51 germinate sshd[3847417]: debug1: /home/zachary/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
        May 08 13:53:51 germinate sshd[3847417]: Accepted key RSA SHA256:Zt8jjAh4Z8iQ1+219IV7eNmSnQ154QbBoJ947jVEDDk found at /home/zachary/.ssh/authorized_keys:1
        May 08 13:53:51 germinate sshd[3847417]: debug1: restore_uid: 0/0
        May 08 13:53:51 germinate sshd[3847417]: Postponed publickey for zachary from 192.168.1.100 port 54350 ssh2 [preauth]
        May 08 13:53:51 germinate sshd[3847417]: debug1: userauth-request for user zachary service ssh-connection method publickey [preauth]
        May 08 13:53:51 germinate sshd[3847417]: debug1: attempt 2 failures 0 [preauth]
        May 08 13:53:51 germinate sshd[3847417]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
        May 08 13:53:51 germinate sshd[3847417]: debug1: trying public key file /home/zachary/.ssh/authorized_keys
        May 08 13:53:51 germinate sshd[3847417]: debug1: fd 5 clearing O_NONBLOCK
        May 08 13:53:51 germinate sshd[3847417]: debug1: /home/zachary/.ssh/authorized_keys:1: matching key found: RSA SHA256:Zt8jjAh4Z8iQ1+219IV7eNmSnQ154QbBoJ947jVEDDk
        May 08 13:53:51 germinate sshd[3847417]: debug1: /home/zachary/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
        May 08 13:53:51 germinate sshd[3847417]: Accepted key RSA SHA256:Zt8jjAh4Z8iQ1+219IV7eNmSnQ154QbBoJ947jVEDDk found at /home/zachary/.ssh/authorized_keys:1
        May 08 13:53:51 germinate sshd[3847417]: debug1: restore_uid: 0/0
        May 08 13:53:51 germinate sshd[3847417]: debug1: auth_activate_options: setting new authentication options
        May 08 13:53:51 germinate sshd[3847417]: debug1: do_pam_account: called
        May 08 13:53:51 germinate sshd[3847417]: Accepted publickey for zachary from 192.168.1.100 port 54350 ssh2: RSA SHA256:Zt8jjAh4Z8iQ1+219IV7eNmSnQ154QbBoJ947jVEDDk
        May 08 13:53:51 germinate sshd[3847417]: debug1: monitor_child_preauth: zachary has been authenticated by privileged process
        May 08 13:53:51 germinate sshd[3847417]: debug1: auth_activate_options: setting new authentication options [preauth]
        May 08 13:53:51 germinate sshd[3847417]: debug1: monitor_read_log: child log fd closed
        May 08 13:53:51 germinate sshd[3847417]: debug1: PAM: establishing credentials
        May 08 13:53:51 germinate sshd[3847417]: debug1: PAM: pam_setcred(): Failure setting user credentials
        May 08 13:53:51 germinate sshd[3847417]: pam_unix(sshd:session): session opened for user zachary(uid=1000) by (uid=0)
        May 08 13:53:51 germinate sshd[3847417]: User child is on pid 3868868

* What exactly did you do (or not do) that was effective (or ineffective)?
    Adding -o PasswordAuthentication=no to the ssh client invocation has no effect, nor does manually specifying -i.

    Removing the line PermitEmptyPasswords, it takes ~250ms on my server.

* What outcome did you expect instead?
    I expect "PasswordAuthentication no" to mean PAM does not check anything about passwords, and to override "PermitEmptyPasswords yes"

I believe this would affect upstream, but I can't confirm.