背景
在openstack上起了一个rocky9 linux的实例，cloud image是我自己通过image-builder编译的，image上传到openstack后创建虚拟机实例，分配external ip，在ssh login的时候发现login不成功，用guestfish 查看sshd_config 发现root用户被禁止登陆，cloud-init 会创建默认用户cloud_user, 然而当我创建了keypair，发现cloud_user 任然无法登陆(进入系统后现cloud-init没执行，cloud_user没创出来)， 于是在guestfish里强行修改了sshd配置，
PermitRootLogin yes
PasswordAuthentication=yes
PermitEmptyPasswords=yes
UsePAM yes
以及 /etc/shadow强行修改了密码，以及注入ssh public key 到/root/.ssh/authorized_keys，
重新上传镜像后通过console， root用户使用密码登陆成功，root用户使用ssh + private key 可以登陆成功,
然而不出意外的话，还是出了意外：
问题描述
root用户使用ssh+正确密码登陆是报错并退出，报错内容client_loop: send disconnect: Broken pipe
使用错误密码以及不输入密码直接回车都不会报错。
系统信息
[root@localhost ~]# cat /etc/rocky-release
Rocky Linux release 9.3 (Blue Onyx)
[root@localhost ~]# rpm -aq | grep openssh
openssh-8.7p1-34.el9.x86_64
openssh-clients-8.7p1-34.el9.x86_64
openssh-server-8.7p1-34.el9.x86_64
问题分析
- 开始一点思路都没有，所以先google下报错，google给出的答案都是修改ssh 参数，ClientAliveInterval，ClientAliveCountMax，
实测对我的情况一点用都没有。
Fix Client_loop: send disconnect: Broken pipe Error
To resolve this issue, you need to increase the SSH connection timeout on the client. To do so, modify the default SSH configuration file which is usually at /etc/ssh/sshd_config.
$ sudo vi /etc/ssh/sshd_config
Be sure to locate these two parameters: ClientAliveInterval and ClientAliveCountMax. Let’s check out what they do.
ClientAliveInterval – This is the period of inactivity after which the SSH server sends an alive message to the remote client that is connected to it.
ClientAliveCountMax – This is the number of attempts that the server will make to send the alive message from the server to the client.
- 怀疑是密码验证阶段除了问题，因为ssh + private key的方式可以login，ssh+password 方式就会出问题，因为使用了pam做密码的验证，所以查看/var/log/secure
Mar 7 09:58:39 localhost sshd[28789]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.20.20.1 user=root
可能是pam模块读取/etc/passwd, /etc/shadow 文件时权限不够，查看文件发现权限没问题
[root@localhost ~]# ll /etc/shadow
-rw-rw-r–. 1 root root 724 Mar 6 10:48 /etc/shadow
[root@localhost ~]# ll /etc/passwd
-rw-r–r–. 1 root root 1045 Mar 6 06:03 /etc/passwd
- 也可能时pam的配置问题，检查/etc/pam.d/sshd
[root@localhost ~]# ll /etc/pam.d/sshd
-rw-r–r–. 1 root root 725 Mar 6 10:59 /etc/pam.d/sshd
从sshd的配置中可以看出auth过程是由子栈 password-auth负责的
[root@localhost ~]# cat /etc/pam.d/sshd
#%PAM-1.0
auth substack password-auth
auth include postlogin
account required pam_sepermit.so
account required pam_nologin.so
account include password-auth
password include password-auth
#pam_selinux.so close should be the first session rule
session required pam_selinux.so close
session required pam_loginuid.so
#pam_selinux.so open should only be followed by sessions to be executed in the user context
session required pam_selinux.so open env_params
session required pam_namespace.so
session optional pam_keyinit.so force revoke
session optional pam_motd.so
session include password-auth
session include postlogin
对password-auth进行检查
[root@localhost ~]# ll /etc/pam.d/password-auth
-rw-r–r–. 1 root root 766 Mar 6 11:16 /etc/pam.d/password-auth
从下面文件可以看出auth过程是由pam_unix.so模块负责的，
[root@localhost ~]# cat /etc/pam.d/password-auth
#%PAM-1.0
#This file is auto-generated.
#User changes will be destroyed the next time authselect is run.
auth required pam_env.so
auth sufficient pam_unix.so try_first_pass nullok
auth required pam_deny.so
account required pam_unix.so
password requisite pam_pwquality.so try_first_pass local_users_only retry=3 authtok_type=
password sufficient pam_unix.so try_first_pass use_authtok nullok sha512 shadow
password required pam_deny.so
session optional pam_keyinit.so revoke
session required pam_limits.so
-session optional pam_systemd.so
session [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
session required pam_unix.so
查看/var/log/message发现，pam_setcred()在对密码校验之后设置user credentials的时候返回失败，这个阶段如果成功，user credentials将用于初始化session阶段，这也是为什么输入密码成功后没有出现session而是直接退出了，但是这里为什么会失败，现有的log还是很难看出，但也可以定位到是pam_unix.so 模块报错
Mar 7 03:08:07 localhost sshd[23813]: Accepted keyboard-interactive/pam for rocky from 192.168.222.239 port 55660 ssh2
Mar 7 03:08:07 localhost sshd[23813]: fatal: PAM: pam_setcred(): Failure setting user credentials
于是给该模块加了debug的参数
auth sufficient pam_unix.so try_first_pass nullok debug
[root@localhost ~]# vi /etc/ssh/sshd_config
LogLevel DEBUG
下面是完整的sshd的pam认证过程，可以发现加粗的部分，由2次关于认证的报错，第一个报错是sudo ssh root@10.20.20.113回车后直接弹出的报错（我还没输入密码，为什么说Authentication failure），第二个报错是输入正确密码后设置credentials的报错（说明Authentication的时候成功了），中间高亮部分是Accepted keyboard-interactive/pam(说明我键盘输入的密码被接受了)
Mar 8 16:25:54 localhost sshd[43584]: debug1: Forked child 43641.
Mar 8 16:25:54 localhost sshd[43641]: debug1: Set /proc/self/oom_score_adj to 0
Mar 8 16:25:54 localhost sshd[43641]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Mar 8 16:25:54 localhost sshd[43641]: debug1: inetd sockets after dupping: 4, 4
Mar 8 16:25:54 localhost sshd[43641]: Connection from 10.20.20.1 port 36194 on 192.168.222.239 port 22 rdomain “”
Mar 8 16:25:54 localhost sshd[43641]: debug1: Local version string SSH-2.0-OpenSSH_8.7
Mar 8 16:25:54 localhost sshd[43641]: debug1: Remote protocol version 2.0, remote software version OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
Mar 8 16:25:54 localhost sshd[43641]: debug1: compat_banner: match: OpenSSH_8.9p1 Ubuntu-3ubuntu0.6 pat OpenSSH* compat 0x04000000
Mar 8 16:25:54 localhost sshd[43641]: debug1: SELinux support enabled [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: ssh_selinux_change_context: setting context from ‘system_u:system_r:sshd_t:s0-s0:c0.c1023’ to ‘system_u:system_r:sshd_net_t:s0-s0:c0.c1023’ [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: permanently_set_uid: 74/74 [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: SSH2_MSG_KEXINIT received [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: kex: algorithm: curve25519-sha256 [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: kex: host key algorithm: ssh-ed25519 [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: compression: none [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: compression: none [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: rekey out after 134217728 blocks [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: Sending SSH2_MSG_EXT_INFO [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: rekey in after 134217728 blocks [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: KEX done [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: userauth-request for user root service ssh-connection method none [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: attempt 0 failures 0 [preauth]
Mar 8 16:25:54 localhost sshd[43641]: debug1: PAM: initializing for “root”
Mar 8 16:25:54 localhost sshd[43641]: debug1: PAM: setting PAM_RHOST to “10.20.20.1”
Mar 8 16:25:54 localhost sshd[43641]: debug1: PAM: setting PAM_TTY to “ssh”
Mar 8 16:25:54 localhost sshd[43641]: pam_unix(sshd:auth): username [root] obtained
Mar 8 16:25:54 localhost sshd[43641]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.20.20.1 user=root
Mar 8 16:25:56 localhost sshd[43641]: debug1: PAM: password authentication failed for root: Authentication failure
Mar 8 16:25:56 localhost sshd[43641]: Failed none for root from 10.20.20.1 port 36194 ssh2
Mar 8 16:25:56 localhost sshd[43641]: debug1: audit_event: unhandled event 3
Mar 8 16:25:57 localhost sshd[43641]: debug1: userauth-request for user root service ssh-connection method publickey [preauth]
Mar 8 16:25:57 localhost sshd[43641]: debug1: attempt 1 failures 0 [preauth]
Mar 8 16:25:57 localhost sshd[43641]: debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:I69j5hxv8GaHAdjKpyPEssEFtGKCCsPWFsBRb+6Y0wY [preauth]
Mar 8 16:25:57 localhost sshd[43641]: debug1: temporarily_use_uid: 0/0 (e=0/0)
Mar 8 16:25:57 localhost sshd[43641]: debug1: trying public key file /root/.ssh/authorized_keys
Mar 8 16:25:57 localhost sshd[43641]: debug1: fd 5 clearing O_NONBLOCK
Mar 8 16:25:57 localhost sshd[43641]: debug1: restore_uid: 0/0
Mar 8 16:25:57 localhost sshd[43641]: Failed publickey for root from 10.20.20.1 port 36194 ssh2: RSA SHA256:I69j5hxv8GaHAdjKpyPEssEFtGKCCsPWFsBRb+6Y0wY
Mar 8 16:25:57 localhost sshd[43641]: debug1: userauth-request for user root service ssh-connection method keyboard-interactive [preauth]
Mar 8 16:25:57 localhost sshd[43641]: debug1: attempt 2 failures 1 [preauth]
Mar 8 16:25:57 localhost sshd[43641]: debug1: keyboard-interactive devs [preauth]
Mar 8 16:25:57 localhost sshd[43641]: debug1: auth2_challenge: user=root devs= [preauth]
Mar 8 16:25:57 localhost sshd[43641]: debug1: kbdint_alloc: devices ‘pam’ [preauth]
Mar 8 16:25:57 localhost sshd[43641]: debug1: auth2_challenge_start: trying authentication method ‘pam’ [preauth]
Mar 8 16:25:57 localhost sshd[43645]: pam_unix(sshd:auth): username [root] obtained
Mar 8 16:25:57 localhost sshd[43641]: Postponed keyboard-interactive for root from 10.20.20.1 port 36194 ssh2 [preauth]
Mar 8 16:26:01 localhost sshd[43645]: debug1: do_pam_account: called
Mar 8 16:26:01 localhost sshd[43641]: debug1: PAM: num PAM env strings 2
Mar 8 16:26:01 localhost sshd[43641]: Postponed keyboard-interactive/pam for root from 10.20.20.1 port 36194 ssh2 [preauth]
Mar 8 16:26:01 localhost sshd[43641]: debug1: do_pam_account: called
Mar 8 16:26:01 localhost sshd[43641]: Accepted keyboard-interactive/pam for root from 10.20.20.1 port 36194 ssh2
Mar 8 16:26:01 localhost sshd[43641]: debug1: monitor_child_preauth: user root authenticated by privileged process
Mar 8 16:26:01 localhost sshd[43641]: debug1: monitor_read_log: child log fd closed
Mar 8 16:26:01 localhost sshd[43641]: debug1: audit_event: unhandled event 2
Mar 8 16:26:01 localhost sshd[43641]: debug1: SELinux support enabled
Mar 8 16:26:01 localhost sshd[43641]: debug1: PAM: establishing credentials
Mar 8 16:26:01 localhost sshd[43641]: fatal: PAM: pam_setcred(): Failure setting user credentials
Mar 8 16:26:01 localhost sshd[43641]: debug1: do_cleanup
Mar 8 16:26:01 localhost sshd[43641]: debug1: temporarily_use_uid: 0/0 (e=0/0)
Mar 8 16:26:01 localhost sshd[43641]: debug1: restore_uid: 0/0
这里产生了疑点，为什么我ssh的时候回车后还没输入密码就开始auth了？
这时候我才意识到我在sshd中设置了PermitEmptyPasswords=yes，并且使用guestfish对/etc/shadow的root用户注入了密码，
所以回车意味着输入了空字符串密码，pam在用空字符串和/etc/shadow中的密码做比较的时候hash结果不一致所以报错了。
第二个疑点是，我在键盘输入密码后验证通过了，为什么会显示Failure setting user credentials？
巧合的是我google里找到了一个非常相似的case,这个case中提供了一段linux pam的stack，{}中的是thread id：
{12568}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_authenticate(108)] called.
{12568}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_authenticate(176)] user=root, password=[]
{12568}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_authenticate(182)] recording return code for next time [7]
{12568}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_authenticate(182)] done. [Authentication failure]
{12574}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_authenticate(108)] called.
{12574}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_authenticate(176)] user=root, password=[1]
{12574}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_authenticate(182)] recording return code for next time [0]
{12574}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_authenticate(182)] done. [Success]
{12574}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_acct.c:pam_sm_acct_mgmt(196)] called.
{12574}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_acct.c:pam_sm_acct_mgmt(202)] user = `root’
{12574}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_acct.c:pam_sm_acct_mgmt(307)] all done
{12568}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_setcred(203)] called.
{12568}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_setcred(209)] recovering return code from auth call
{12568}[…/…/…/Linux-PAM-1.3.0/modules/pam_unix/pam_unix_auth.c:pam_sm_setcred(217)] recovered data indicates that old retval was 7
从这段stack log中，可以看出
线程 1 尝试使用空密码进行身份验证，此操作失败并且失败被缓存在线程 1 上下文中
线程 2 尝试再次进行身份验证，这次使用用户提供的密码成功并且成功被缓存在线程 2 上下文中
线程 1 尝试设置凭据，该凭据使用线程 1 中缓存的失败的上下文
对 pam_sm_setcred() 的调用应该是来自成功调用 pam_sm_authenticate() 的同一线程即{12574}
线程 2 看起来像是从线程 1 中分叉出来的，因为当它被调用时，它知道之前的身份验证失败，并且它正确地将之前的（失败）返回代码替换为新的（成功）返回代码。
但是，父进程没有此更新的结果代码，而只能看到之前的失败的。
从该帖中的信息来看是一个亿提交的bug，大概意思是空密码验证和输入密码验证使用了不同的线程，当线程2更新了认证结果，
父线程在做pam_sm_setcred的时候却没拿到线程2更新的正确结果，导致pam_sm_setcred失败。。。
解决办法
于是我修改了/etc/ssh/sshd_config 中PermitEmptyPasswords的参数为no， systemctl restart sshd时候再次ssh login，嘿！你猜怎么着？
.
.
.
当然是问题解决了。
793
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
