背景
大家工作时,少不了ssh登录各个服务器,我这边手里也有很多服务器,有一些登录很快就进去了,有些要卡半天才能进去。之前以为是公司网络问题,每次也就忍了,这次突然不想忍了,决定定位一下。
我这边的服务器是10.80.121.46。因为这个问题是可复现的,算是个好问题,于是在本地开了wireshark,ssh登录,看看能不能看出端倪。
host 10.80.121.46 and tcp port 22
可以看到,服务端在00:13,发了第一个消息过来;过了20s,发了第二个消息过来。
总的来说,应该是服务端问题。
定位过程
看日志
由于是ssh这种加密了的协议,抓包也看不出个啥。所以我首先的思路是看看sshd这个服务端进程的日志。sshd是systemd管理的,所以看看状态先。
这种的话,一般也能看到最新的日志,如果要看完整的日志,可以用如下命令:
journalctl -u sshd
ps: journalctl -u sshd -f 可以像tailf那样持续跟踪日志
但是,发现只有info级别的日志,也看不出什么特别.
Apr 03 15:27:30 nginx2 sshd[87616]: Accepted password for root from 10.0.235.72 port 11481 ssh2
接下来,又看了下其他日志:
/var/log/messages:
Apr 3 15:27:30 year-account-nginx2 systemd-logind: New session 13336 of user root.
Apr 3 15:27:30 year-account-nginx2 systemd: Started Session 13336 of user root.
/var/log/secure:
Apr 3 15:27:30 year-account-nginx2 sshd[87616]: Accepted password for root from 10.0.235.72 port 11481 ssh2
Apr 3 15:27:30 year-account-nginx2 sshd[87616]: pam_unix(sshd:session): session opened for user root by (uid=0)
反正看了好些日志,没啥用,这边上个链接,讲linux下的各种日志。
https://www.plesk.com/blog/featured/linux-logs-explained/
https://www.eurovps.com/blog/important-linux-log-files-you-must-be-monitoring/
开启debug日志
上网查了下,怎么开启sshd的debug级别日志,结论如下:
vim /etc/ssh/sshd_config
加一行:
LogLevel DEBUG
这个LogLevel的取值有哪些呢,具体可以在机器上执行:
man sshd_config
没想到取值还有更逆天的:
我之前就是在debug级别下测试的,然后看日志:
journalctl -u sshd -f
看到出现了20s的间隔,但是,还是没有什么错误或者警告。当时,我就开始上网查了,但是这次,咱们要不试试把日志级别弄成DEBUG3:
这里日志细了一些,但还是看不太出来啥问题。这个10.0.235.72,是我本机windows的ip。
服务端dns抓包
经过上网冲浪,发现很多文章提到了一点,就是sshd会拿着我们客户端的ip,去dns 服务器查询ip对应的主机名(域名)。很明显,我这个ip,肯定是没什么域名的。大概率是这个原因,但是基于严谨的角度考虑,我还是先找找证据。
dns服务器对外的端口是53,所以我抓的就是这个端口的网络包:
可以发现,本机是给两个dns服务器发请求的,分别是8.8.8.8 8.8.4.4
看下机器的dns服务器配置:
vim /etc/resolv.conf
nameserver 8.8.8.8
nameserver 8.8.4.4
不知道为啥是这个地址,反正是运维同事给的。
测试了端口通不通,发现tcp不通,udp不知道咋测(试了下netcat、nmap,没太弄懂)
ping也不通,不知道是真不通,还是对端禁ping了。
这些都不重要,重要的是,这个报文也不知道是啥意思,看起来和我的问题没什么关系。
strace排查
暂时放下dns这块,准备strace试试,反正,死马当活马医。
strace这个一般用得少,选项记不住,一开始就这么试试:
netstat -nltp|grep 22
tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN 93585/sshd
tcp 0 0 0.0.0.0:4822 0.0.0.0:* LISTEN 31633/nginx: master
tcp6 0 0 :::22 :::* LISTEN 93585/sshd
拿到sshd pid为93585,开启strace:
但是啥也没看出来。
找了下以前笔记,加了几个选项:
strace -p 121920 -s 1000 -t -e trace=network,file,desc,process
-s: 字符串显示1000个字符串,不截断(默认是32,会看不全)
-t:显示时间
-e trace=network,file,desc,process,监控网络、文件、文件描述符、进程相关的系统调用
这次信息多一点,还是啥都看不出来。
上网查
没法了,把之前dns抓的包拿下来用wireshark分析分析。
这个dns查询,有点看不懂,直接拿关键字搜了下,大家看如下链接吧:
https://www.cloudflare.com/zh-cn/learning/dns/dns-records/dns-ptr-record/
难怪,dns进行反向查找时,客户端ip是反的,我的实际ip是:10.0.235.72
到了上图,就变成了:
也难怪我没看出来,这个基本算是一个强力证据了,大概率是dns解析的问题,毕竟用了我的ip。
修改sshd配置
那就禁用这个机制吧,方式如下:
vim /etc/ssh/sshd_config
UseDNS no
然后重启sshd
systemctl restart sshd
这样基本就ok了。重新试了下,再没有卡20s了,秒登录。
继续探索strace
找到问题原因后,strace我又继续研究了下。原来是少了个选项,-f:
-f
--follow-forks
Trace child processes as they are created by currently traced processes as a result of the fork(2), vfork(2) and
clone(2) system calls. Note that -p PID -f will attach all threads of process PID if it is multi-threaded, not only
thread with thread_id = PID.
这个选项是跟踪子进程的系统调用,因为,sshd收到一个客户端连接时,会fork一个新进程出来。前面都忘了加-f,所以导致没跟踪到。
换下命令:
strace -p 93585 -s 1000 -t -e trace=network,file,desc,process -f
这次可以跟踪了。
补充
在写这篇文章的时候,对一个地方产生了疑问。一般看日志的时候,对于systemd管理的service,我会看journalctl,也会看/var/log/messages,经常的情况是,在journalctl中的日志,在/var/log/messages中也能看到。
查了下两者的机制,参考:
systemd会写日志到一些文件(journalctl就会读这些文件),然后,另一个后台进程rsyslogd,也会读这些日志,然后写到/var/log/messages这些文件中。
[root@year-account-nginx2 log]# ps -ef|grep rsys
root 1614 1 0 2022 ? 00:46:28 /usr/sbin/rsyslogd -n
标签:sshd,log,strace,0.0,20s,ssh,dns,日志,太慢
From: https://www.cnblogs.com/grey-wolf/p/18113149