不知从何时起,ServerDog与一台CentOS服务器的ssh连接变得很不稳定,时不时收到报错:
com.dancen.serverdog.handler.server.ServerRunnable > run > 54
java.io.IOException: connect ssh[dancen@10.17.1.10:22] failed
一. 查找原因,有以下现象
1. 查看ServerDog日志发现,ServerDog已经无法与该服务器建立ssh连接。
2. 通过XShell客户端能够与该服务器建立ssh连接,但是建立连接过程比较慢,耗时1分钟左右,而且连接成功后发现该服务器比较卡。
首先简单粗暴祭出重启大法。重启后,XShell连接该服务器依然缓慢,但是连接成功后,服务器不再卡顿。
3. 服务器负载高。
然而,过一段时间后,服务器又会变得非常卡顿。通过uptime命令可以看到服务器负载非常高。
4. CPU在IO等待部分占比非常高。
该服务器基本属于闲置状态,并没有运行什么高开销的应用,为何负载居高不下?通过top命令观察,服务器的CPU用户占用和系统占用并不高,这和预期一致,但CPU的wa占用,即IO等待方面的占用非常高。
5. ssh进程IO操作强度高。
CPU wa占比高说明服务器IO操作遇到了瓶颈,经过查看发现服务器的IO Read操作强度非常大,通过iotop命令可以看到,若干ssh进程大量执行了IO操作。这些ssh进程哪来的呢?应该是监控服务器ServerDog为了获取该服务器的状态而发起的,于是暂时关闭ServerDog服务器,之后服务器的负载恢复正常,服务器不再卡顿。
6. ssh打开会话非常缓慢。
为什么ServerDog的几个ssh连接会导致服务器如此卡顿?在本地经过代码调试可知,ServerDog无法通过ssh操作该服务器。ServerDog在通过ssh连接该服务器时,connect成功后,无法打开会话,因此无法执行后续操作:
java.io.IOException: Could not open channel (The connection is being shutdown)
at com.trilead.ssh2.channel.ChannelManager.waitUntilChannelOpen(ChannelManager.java:127)
at com.trilead.ssh2.channel.ChannelManager.openSessionChannel(ChannelManager.java:584)
而多个ssh连接长时间无法成功建立导致多个ssh连接堆叠,所以在该服务器上会看见多个ssh进程。
为什么会出现该报错呢,这是因为在open channel成功之前,ssh就因为超时被关闭了。作为验证,将测试代码中ssh的connectTimeout和soTimeout设置得足够大,发现ServerDog是可以正常连接并操作该服务器的。这已通过XShell连接该服务器时连接耗时很久的现象是一致的。
至此该服务器卡顿的原因已经明确:
ServerDog在与该服务器建立ssh连接时,由于建连缓慢,多个ssh连接堆叠,建连过程IO操作频繁导致服务器卡顿。
7. 核心问题:为什么ssh建立连接如此缓慢?
[xxx]#ssh -v -p22 dancen@10.17.1.10
debug1: Authentication succeeded (password).
Authenticated to 10.17.1.10 ([10.17.1.10]:22).
debug1: channel 0: new [client-session]
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: pledge: network
可以看到,connect很快,然后是提交密码,也很快通过认证,但是到达
pledge: network
这一步时,需要卡住几十秒,甚至几分钟才能成功打开会话。
二. 解决尝试
网上查看发现,很多用户都有碰到ssh登录卡在pledge: network这一步的情况,但是造成这一现象的原因和解决办法却多种多样。
1. 重启服务器无效。
该服务器并非一直就ssh连接缓慢,而是不知从何时起才出现的。重启大法前面已经尝试过了,无效。
2. 重置sshd_config无效。
会不会是sshd_config配置的问题,直接从其他服务器拷贝配置替换,重启ssh,无效。
3. 清理/var/log下的btmp、secure、wtmp文件无效。
网上有说法,ssh遭到爆破,引起btmp日志文件过大也会导致ssh登录缓慢,我查看该日志文件,确实体积可观,于是清空之,并且将同样巨大的secure、wtmp也清空:
echo “” > btmp
echo “” > secure
echo “” > wtmp
然而,无效。
4. 重启dbus、systemd-logind无效。
网上有说法,重启这两个服务可以解决ssh登录缓慢的问题,然而我连整个服务器都重启过了也未能解决ssh登录的问题,因此重启这两个服务应该是无效的,但还是试试吧:
systemctl restart dbus
systemctl restart systemd-logind
果然无效!
5. 修改sshd_config,设置UseDNS为no无效。
这也是网上的说法,然而我的服务器上该配置本来就是no,无效。
6. 修改sshd_config,设置UsePAM为no。
当开启UsePAM的时候,先去找验证模块,由验证模块决定下一步的验证。
(如/etc/pam.d/sshd文件里面的auth include password-auth)即使密码是正确的,如果验证模块自身有问题也无法登录。
PAM检验的优先级高于PasswordAuthentication(密码验证)。
将UsePAM设为no,重启ssh后,问题解决。
目前建立ssh连接非常快了,但执行su操作切换用户时,仍然有一定的卡顿。
三. PAM认证
一探究竟,为何PAM认证会导致ssh登录慢得难以接受。
1. 重新修改sshd_config,设置UsePAM为yes。
查看ssh的PAM设置:
cat /etc/pam.d/sshd
#%PAM-1.0
auth required pam_sepermit.so
auth substack password-auth
auth include postlogin
# Used with polkit to reauthorize users in remote sessions
-auth optional pam_reauthorize.so prepare
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 include password-auth
session include postlogin
# Used with polkit to reauthorize users in remote sessions
-session optional pam_reauthorize.so prepare
2. 经测试发现,当注销掉/etc/pam.d/sshd中以下内容后,ssh登录慢的问题可以解决。
session include password-auth
以上内容表示会话使用password-auth认证。
3. 进一步探索,取消以上步骤的注释,查看password-auth的PAM配置。
cat /etc/pam.d/password-auth
#%PAM-1.0
# This file is auto-generated.
# User changes will be destroyed the next time authconfig is run.
auth required pam_env.so
auth sufficient pam_unix.so nullok try_first_pass
auth requisite pam_succeed_if.so uid >= 1000 quiet_success
auth required pam_deny.so
account required pam_unix.so
account sufficient pam_localuser.so
account sufficient pam_succeed_if.so uid < 1000 quiet
account required pam_permit.so
password requisite pam_pwquality.so try_first_pass local_users_only retry=3 authtok_type=
password sufficient pam_unix.so sha512 shadow nullok try_first_pass use_authtok
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
经过测试,可以发现,注释掉以下内容:
-session optional pam_systemd.so
ssh登录缓慢的问题可以解决。
4. 经过以上测试可知,ssh登录缓慢的原因在于:
pam_systemd.so
pam_systemd 将用户会话注册到 systemd 登录管理器(也就是 systemd-logind.service(8) 服务)中, 因此也同时注册到了 systemd 控制组(control group)之中。
在登录(login)时,此模块与 systemd-logind.service 服务一起, 确保实现如下功能:
如果用户运行时目录(/run/user/$UID)不存在, 那么就创建该目录或者以"tmpfs"文件系统挂载该目录, 同时根据登录用户为该目录设置磁盘配额、属主与属组。
设置 $XDG_SESSION_ID 环境变量的值。 如果开启了审计并且 pam_loginuid.so 运行在此模块之前(强烈建议这么做), 那么将使用审计会话ID(/proc/self/sessionid)的值, 否则将使用独立的会话计数器的值。
为会话创建一个新的 scope 单元。如果此会话是该用户多个并行会话中第一个建立的会话, 那么将会在 user.slice 之下自动创建一个针对该用户的 slice 单元,并将新建的 scope 单元置于其中。 按照会话用户的身份启动一个 user@.service 系统服务实例 (也就是运行一个 systemd 用户实例)。
在退出(logout)时,此模块确保实现如下功能:
如果在 logind.conf(5) 中设置了 KillUserProcesses=yes (无论明确还是隐含), 那么将会杀死会话中的所有进程。如果此会话是该用户多个并行会话中最后一个退出的会话, 那么还会同时终止该用户的 systemd 用户实例以及 slice 单元。
如果此会话是该用户多个并行会话中最后一个退出的会话, 那么将会删除该用户的运行时目录(/run/user/$UID) 以及其中的所有内容。
如果系统的 init 进程不是 systemd , 那么此模块什么也不做,并且立即返回 PAM_SUCCESS 值。
5. 所以ssh登录缓慢的原因的原因在于:
systemd-logind.service
systemd-logind 是一个管理用户登录的系统服务。 其职责如下:
持续跟踪用户的会话、进程、空闲状态。 这将在 user.slice 之下,为每个用户分配一个 slice 单元、为每个用户的当前会话分配一个 scope 单元。 同时,针对每个已登录的用户,将会启动一个专属的服务管理器(作为 user@.service 模版的一个实例)。
生成并管理"session ID"。如果启用了审计并且已经为一个会话设置了审计"session ID", 那么该ID也将同时被用作"session ID", 否则将会使用一个独立的会话计数器(也就是独立生成一个"session ID")。
为用户的特权操作(例如关闭或休眠系统) 提供基于 polkit 的认证与授权
为应用程序实现 阻止关闭/休眠系统的逻辑
处理 硬件关机/休眠按钮的动作
多席位(Multi-Seat)管理
会话切换管理
管理 用户对设备的访问
在启动虚拟终端时 自动启动文本登录程序(agetty), 并管理用户的运行时目录。
用户会话是通过 pam_systemd(8) PAM 模块 在 logind 中注册的。
6. 饶了一圈,最终还是回到了systemd-logind.service。
前面已经提到过重启该服务的解决方案,现在我们再尝试一次。
[xxx]#systemctl start systemd-logind.service
Failed to start systemd-logind.service: Activation of org.freedesktop.systemd1 timed out
See system logs and 'systemctl status systemd-logind.service' for details.
居然无法启动(之前好像是可以的呀!!!)。
[xxx]#systemctl restart systemd-logind
Job for systemd-logind.service failed. See "systemctl status systemd-logind.service" and "journalctl -xe" for details.
[xxx]# systemctl status systemd-logind.service
● systemd-logind.service - Login Service
Loaded: loaded (/usr/lib/systemd/system/systemd-logind.service; static; vendor preset: disabled)
Active: activating (start) since Fri 2021-04-09 20:20:08 CST; 21s ago
Docs: man:systemd-logind.service(8)
man:logind.conf(5)
http://www.freedesktop.org/wiki/Software/systemd/logind
http://www.freedesktop.org/wiki/Software/systemd/multiseat
Main PID: 1857 (systemd-logind)
CGroup: /system.slice/systemd-logind.service
└─1857 /usr/lib/systemd/systemd-logind
[xxx]# journalctl -xe
-- Unit systemd-udevd-control.socket has begun shutting down.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Closed udev Kernel Socket.
-- Subject: Unit systemd-udevd-kernel.socket has finished shutting down
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit systemd-udevd-kernel.socket has finished shutting down.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Stopping udev Kernel Socket.
-- Subject: Unit systemd-udevd-kernel.socket has begun shutting down
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit systemd-udevd-kernel.socket has begun shutting down.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Starting Cleanup udevd DB...
-- Subject: Unit initrd-udevadm-cleanup-db.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit initrd-udevadm-cleanup-db.service has begun starting up.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Started Cleanup udevd DB.
-- Subject: Unit initrd-udevadm-cleanup-db.service has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit initrd-udevadm-cleanup-db.service has finished starting up.
--
-- The start-up result is done.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Reached target Switch Root.
-- Subject: Unit initrd-switch-root.target has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit initrd-switch-root.target has finished starting up.
--
-- The start-up result is done.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Starting Switch Root.
-- Subject: Unit initrd-switch-root.target has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit initrd-switch-root.target has begun starting up.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Started Plymouth switch root service.
-- Subject: Unit plymouth-switch-root.service has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit plymouth-switch-root.service has finished starting up.
--
-- The start-up result is done.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Starting Switch Root...
-- Subject: Unit initrd-switch-root.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit initrd-switch-root.service has begun starting up.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd[1]: Switching root.
Apr 10 02:10:46 izwz94hdjm5n95l3qbts1vz systemd-journal[89]: Journal stopped
-- Subject: The journal has been stopped
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- The system journal process has shut down and closed all currently
-- active journal files.
更恐怖、更奇怪的是,不执行这个systemd-logind.service的start或者restart还好,一旦执行启动systemd-logind.service失败后,很多命令都不能正常执行了,甚至连reboot命令都报错,不可理喻,无法理解。
[xxx]# reboot
PolicyKit daemon disconnected from the bus.
We are no longer a registered authentication agent.
7. 突然脑子中出现一个想法,难道出现这一切问题的原因是因为该服务器的root用户的名称已经被重命名,而系统存在bug。
验证之,将root用户重新重命名回root。
一切恢复正常,ssh登录秒连,su操作秒切用户。
不可理喻,无法理解!!!