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

Package: openssh-server
Version: 1:8.4p1-5+deb11u1
Severity: normal
X-Debbugs-Cc: [email protected]

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: [email protected] MAC: <implicit> compression: none [preauth]
        May 08 13:53:48 germinate sshd[3847417]: debug1: kex: server->client cipher: [email protected] 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.

-- System Information:
Debian Release: 11.7
  APT prefers stable-updates
  APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 5.10.0-20-amd64 (SMP w/4 CPU threads)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_WARN, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages openssh-server depends on:
ii  adduser                3.118
ii  debconf [debconf-2.0]  1.5.77
ii  dpkg                   1.20.12
ii  libaudit1              1:3.0-2
ii  libc6                  2.31-13+deb11u6
ii  libcom-err2            1.46.2-2
ii  libcrypt1              1:4.4.18-4
ii  libgssapi-krb5-2       1.18.3-6+deb11u3
ii  libkrb5-3              1.18.3-6+deb11u3
ii  libpam-modules         1.4.0-9+deb11u1
ii  libpam-runtime         1.4.0-9+deb11u1
ii  libpam0g               1.4.0-9+deb11u1
ii  libselinux1            3.1-3
ii  libssl1.1              1.1.1n-0+deb11u4
ii  libsystemd0            247.3-7+deb11u2
ii  libwrap0               7.6.q-31
ii  lsb-base               11.1.0
ii  openssh-client         1:8.4p1-5+deb11u1
ii  openssh-sftp-server    1:8.4p1-5+deb11u1
ii  procps                 2:3.3.17-5
ii  runit-helper           2.10.3
ii  ucf                    3.0043
ii  zlib1g                 1:1.2.11.dfsg-2+deb11u2

Versions of packages openssh-server recommends:
ii  libpam-systemd [logind]  247.3-7+deb11u2
ii  ncurses-term             6.2+20201114-2+deb11u1
ii  xauth                    1:1.1-1

Versions of packages openssh-server suggests:
pn  molly-guard   <none>
pn  monkeysphere  <none>
pn  ssh-askpass   <none>
pn  ufw           <none>

-- debconf information excluded