2020年3月

近来一直在做部门疑难问题的排查工作,最近也准备在周分享上做一个小培训(交流)——“排查问题的方法和思路”。回想历史问题处理,觉得这是个很不错的案例,便回溯了一下排查过程记录下来。

一、问题背景

有一个应用层程序,依赖信号接收配置更新事件。

即程序依赖某个配置文件,当配置更新后,需要通过信号告知程序也做相应的更新。

番外故事篇

正常情况下,上面描述的这个机制是没有问题的。

直到有一天,测试同学跑来跟我说:“你的配置更新有bug”,这才结束了这美好的宁静。

虽然我本能的第一反应也是“傻逼你会用吗”,但是我还是假装很淡定的对他说:“bug发来看下”(实际上心里已经想好接下来要怎么怼他了)。然而,事出意料之外,竟然真的有bug,我亲手写出来的bug竟然真的不生效了????

二、排查过程

第一步,理清排查思路。排查的方向是信号为什么不生效,不生效可能是信号被屏蔽了,因此首先要确认的是信号状态。查看/proc/${pid}/status确认信号状态:

图中只列出了关键的几行,各行含义:

  • SigPng: 表示未决信号
  • SigBlk: 表示阻塞信号
  • SigIgn: 表示忽略信号
  • SigCgt: 表示已经捕获的信号

数值都是十六进制表示的数字,通过对比分析发现,SigIgn行刚好就有我通知更新的信号,说明进程屏蔽了信号。但是这怎么可能,代码中明明是需要捕获这个信号的,为什么在这里就被屏蔽了。

这里一度百思不得其解,没有什么思路继续排查。场景就像是,某天东西突然被偷了,但是没有监控,要找出偷东西的人。于是在经过了多轮精神折磨后,我选择了重启进程。

果然,重启后,问题解决了。然而,bug并没有解决,更恐怖的是,问题无法重现了!BUG根本没法查下去。

这也是一个教训,在测试环境下,有条件去查的时候,尽量不要重启服务,不然问题无法重现就麻烦了。

直到了N天后,测试决定放弃这个bug的时候,问题又重现了,但是测试也不知道是什么操作导致它重现的,它也是测试其他案例时候偶然发现功能又不生效的。这就大大增加了排查难度,前无因后无果,依旧无法下手。

没办法,捋清楚思路,继续往下查。先找两个环境对比信号状态,发现没问题的环境信号是没有被屏蔽,但是有问题的环境信号确实被屏蔽了。这说明,正常情况下程序肯定是没有问题的,一定是有某个外部操作导致了环境异常。

这时候,我的思路放在了是什么操作导致异常上,这也是大部分人都会考虑到的点。于是我通过最近一天的访问日志和历史操作日志来反推可能的操作,但是找了很长时间后,都没有定位到具体触发操作,范围实在是太大了。

。。。

直到一天过去后,我和测试同学才终于找到了触发问题的操作,触发的操作是在前端页面上同步了一下系统时间。因为环境刚启动的时候设备时间不对,测试同学手动同步了一下时间,这才产生了这个问题。

找到了触发条件后,问题就好查了,追踪代码流程,发现同步系统时间后,会把所有的服务重启。具体的流程为:

关键点就在于这重启服务上,我们的web服务是部署了一个apache,apache重启后台服务的时候导致它变成了所有服务的父进程。而创建子进程的时候,所有子进程都会继承父进程的信号屏蔽字,刚好apache就屏蔽了这个信号,导致所有被拉起的子进程都无法接受到这个信号。至此,问题的原因也就明了了。

解决方案

创建子进程后,通过信号集sigset_t相关的函数接口,清空子进程所有的信号屏蔽字。让子进程自己重新注册信号处理函数。

三、思路分析和总结

其实通过重启操作就能明显发现异常的地方是重启,因为重启之后没有现象了,说明问题肯定和重启相关。这个时候只要ps看一下进程状态,是不是被重启过了,再看一下父进程的pid就能大概发现问题了,而不用花大量的时间去定位重现操作。

总结:处理问题的思路太局限了,换个思路可能一下就查出来了,要善于抓住问题的关键点。

一、socks5协议

socks5协议是一款广泛使用的代理协议,它在使用TCP/IP协议通讯的前端机器和服务器机器之间扮演一个中介角色,使得内部网中的前端机器变得能够访问Internet网中的服务器,或者使通讯更加安全。SOCKS5 服务器通过将前端发来的请求转发给真正的目标服务器, 模拟了一个前端的行为。在这里,前端和SOCKS5之间也是通过TCP/IP协议进行通讯,前端将原本要发送给真正服务器的请求发送给SOCKS5服务器,然后SOCKS5服务器将请求转发给真正的服务器。

代理的工作流程图为:

二、socks5协议交互过程

2.1 基于TCP的客户端连接过程

第一步,客户端向代理服务器发送代理请求,其中包含了代理的版本和认证方式:

                   +----+----------+----------+
                   |VER | NMETHODS | METHODS  |
                   +----+----------+----------+
                   | 1  |    1     | 1 to 255 |
                   +----+----------+----------+

如果是socks5代理,第一个字段VER的值是0x05,表明是socks代理的第5个版本。

第二个字段NMETHODS表示支持的认证方式,第三个字段是一个数组,包含了支持的认证方式列表:

  • 0x00: 不需要认证
  • 0x01: GSSAPI认证
  • 0x02: 用户名和密码方式认证
  • 0x03: IANA认证
  • 0x80-0xfe: 保留的认证方式
  • 0xff: 不支持任何认证方式

服务端收到客户端的代理请求后,选择双方都支持的加密方式回复给客户端:

                         +----+--------+
                         |VER | METHOD |
                         +----+--------+
                         | 1  |   1    |
                         +----+--------+

此时客户端收到服务端的响应请求后,双方握手完成,开始进行协议交互。

数据包分析

客户端开启socks代理,使用浏览器访问网页。抓包软件抓到客户端的认证请求:

服务端的认证响应请求:

2.2 请求

握手完成后,客户端要把需要执行的操作指令发给客户端,表明自己要执行代理的请求。请求帧格式:

        +----+-----+-------+------+----------+----------+
        |VER | CMD |  RSV  | ATYP | DST.ADDR | DST.PORT |
        +----+-----+-------+------+----------+----------+
        | 1  |  1  | X'00' |  1   | Variable |    2     |
        +----+-----+-------+------+----------+----------+

各字段含义:

  • VER: 代理版本信息
  • CMD: 代理指令

    • 0x01: connect指令,tcp代理时使用。
    • 0x02: bind,很少使用,类似FTP协议中主动连接场景,服务端后服务端会主动连接到客户端。
    • 0x03: udp代理时使用。
  • RSV: 保留字段
  • ATYP: 地址类型

    • 0x01: IPv4地址类型
    • 0x03: unix域socket类型代理
    • 0x04: IPv6地址类型
  • DST.ADDR: 需要连接的目的地址
  • DST.PORT: 需要连接的目的端口

数据包分析

以下是一个去往console.cloud.tencent.com:443的socks5代理请求:

2.3 响应

客户端发完上面的请求连接后,服务端会发起连接到DST.ADDR:DST.PORT,然后返回响应到客户端,响应格式:

        +----+-----+-------+------+----------+----------+
        |VER | REP |  RSV  | ATYP | BND.ADDR | BND.PORT |
        +----+-----+-------+------+----------+----------+
        | 1  |  1  | X'00' |  1   | Variable |    2     |
        +----+-----+-------+------+----------+----------+

其中VER/RSV/ATYP的含义和上面相同,其他字段的意思:

  • REP: 请求响应

    • 0x00: 成功
    • 0x01-0x08: 失败
    • 0x09-0xff: 未使用
  • BND.ADDR: 连接到的远程地址
  • BND.PORT: 连接到的远程端口

数据包分析

以下是上面代理请求的响应数据包:

2.4 代理通信

当连接建立后,客户端就可以和正常一样访问服务端通信了,此时通信的数据除了目的地址是发往代理程序以外,所有内容都是和普通连接一模一样。对代理程序而言,后面所有收到的来自客户端的数据都会原样转发到服务读端。

例如代理的HTTPS请求连接,实际上发送的数据和普通HTTPS交互过程一模一样:

中间的Socks Protocol栏是wireshark根据连接上下文自动解析出来的,实际上数据包中并没有这一栏。

三、流程图

socks5通信的交互流程:

四、参考

RFC1928 - SOCKS Protocol Version 5

RFC1929 - Username/Password Authentication for SOCKS V5

ss5项目主页:http://ss5.sourceforge.net/,下载地址:https://sourceforge.net/projects/ss5/files/

先下载下来源码包,解压:

tar -zxvf ss5-3.8.9-8.tar.gz
cd ss5-3.8.9

安装依赖项:

yum install epel-release
yum update -y

yum groupinstall 'Development Tools' -y
yum install gcc automake autoconf libtool make yum-utils wget -y

yum install pam-devel openldap-devel openssl-devel -y

编译程序并安装:

./configure
make && make install

make的时候如果报下面的错误,说明是gcc版本太高了导致,需要使用低版本的(gcc4)来编译:

ss5-3.8.9/src/SS5Core.c:839: undefined reference to `S5DebugUdpRequestInfo'
ss5-3.8.9/src/SS5Core.c:842: undefined reference to `S5ChildClose'
ss5-3.8.9/src/SS5Core.c:843: undefined reference to `S5ChildClose'
ss5-3.8.9/src/SS5Core.c:866: undefined reference to `S5ChildClose'
ss5-3.8.9/src/SS5Core.c:759: undefined reference to `S5DebugUpstreamInfo'
ss5-3.8.9/src/SS5Core.c:397: undefined reference to `S5ChildClose'
collect2: error: ld returned 1 exit status
make[1]: *** [ss5] Error 1
make[1]: Leaving directory `ss5-3.8.9/src'
make: *** [src] Error 2
安装完成后,默认的配置文件在/etc/opt/ss5/ss5.conf,日志文件在/var/log/ss5/ss5.log

修改配置文件,去掉下面两行的注释:

auth    0.0.0.0/0               -               -
permit -    0.0.0.0/0    -    0.0.0.0/0    -    -    -    -    -

这两行是认证相关的参数,去掉注释表示使用默认的认证参数(不需要认证并允许所有IP代理)。ss5程序支持多种认证方式,包括密码认证以及ldap认证等,这里测试使用不需要认证。

服务默认监听1080端口,启动服务的办法:

ss5 -t -u root

参数说明:

  • -t: 使用多线程模式
  • -u: 指定启动用户
  • -p: 指定pid文件路径

测试代理是否成功:

加入systemd服务

配置文件:

[Unit]
Description=SS5 Socks Proxy
After=syslog.target network.target nss-lookup.target

[Service]
Type=forking
PIDFile=/var/run/ss5.pid
ExecStart=/sbin/ss5 -p /var/run/ss5.pid -u root

[Install]
WantedBy=multi-user.target

参考

Install ss5 on CentOS7 to implement SOCKS5 proxy service

Ss5 official document

Socks5 Secure Username and Password Authorization Agreement

一、问题现象

使用item2登录到远程linux后,系统的语言编程了中文:

本来对于中国人来说,使用中文没有什么不好。但是报错信息是中文就导致出问题了不好查,百度和google查不到相关信息。比较尴尬!

二、解决办法

通过locale命令查看当前终端的语言和字符编码信息:

[root@centos7:~]$ locale
LANG=zh_CN.UTF-8
LC_CTYPE="zh_CN.UTF-8"
LC_NUMERIC="zh_CN.UTF-8"
LC_TIME="zh_CN.UTF-8"
LC_COLLATE="zh_CN.UTF-8"
LC_MONETARY="zh_CN.UTF-8"
LC_MESSAGES="zh_CN.UTF-8"
LC_PAPER="zh_CN.UTF-8"
LC_NAME="zh_CN.UTF-8"
LC_ADDRESS="zh_CN.UTF-8"
LC_TELEPHONE="zh_CN.UTF-8"
LC_MEASUREMENT="zh_CN.UTF-8"
LC_IDENTIFICATION="zh_CN.UTF-8"
LC_ALL=

通过第一行输出可以看到语言是zh_CN.UTF-8,说明当前bash使用的是中文语言。

修改方法

~/.bashrc中修改语言控制相关的环境变量:

export LC_ALL=en_US.UTF-8
export LANG=en_US.UTF-8

然后source ~/.bashrc生效:

一、问题现象

客户报障,说使用了我们的网关设备后网络经常中断。具体的情形是用我们设备做代理上网后,流量图显示流量每隔两分钟就会直线下跌一次,同时就伴随着内网用户断网。

经过排查后发现问题原因是设备负载太高了导致,出问题时候的负载趋势图为:

从图形来看,负载是每1-2分钟就会上升一次,而且上升得特别明显,最高到达了五十多。但设备只是一个4核的设备,这么高的负载肯定是无法承受了。可以断定断网是负载高导致的。

于是继续分析mpstat中对CPU的采样,看看是什么原因导致的设备负载高:

linux 2.6.30-os (localhost) 02/27/20 _x86_64_    (4 CPU)

Average:     CPU    %usr   %nice    %sys   %soft  %idle
Average:     all   17.50    4.75   18.00   29.75  27.75
Average:       0   17.00    5.00   16.00    4.00  57.00
Average:       1   17.17    0.00   18.18   60.61   0.00
Average:       2   16.16   13.13   16.16    1.01  53.54
Average:       3   20.00    0.00   21.00   54.00   1.00

从cpu抽样数据可以看到,出问题的时候,有2个CPU都已经跑满了,其中占用最高的是soft,两个核占用都超过了一半。soft是系统软中断调用,是内核层面的原因导致,需要进一步排查内核中的问题。

内核问题一般回打印到messages或者dmesg,我们的设备是都保存到了一个dmesg文件中,因此下一步思路就是分析dmesg了。果然,查看dmesg就看到了大量的错误信息:

TCP: time wait bucket table overflow
...
Out of socket memory
...
TCP: too many of orphaned sockets

经过查找资料后,整理出来三个错误日志的意思:

  • TCP: too many of orphaned sockets: 太多的孤儿socket
  • Out of socket memory: socket占用的内存超出
  • TCP: time wait bucket table overflow: 保存TIME-WAIT状态socket的哈希表槽溢出

对比错误日志产生的时间和系统负载增加的时间发现两者都能对上,负载高的时候打印日志更频繁,负载低的时候几乎没有什么日志。这就说明导致负载高的原因和这三条日志有关了,下一步思路是分析为什么要打印这些日志了。

二、分析孤儿socket

2.1 什么是孤儿socket

说到孤儿socket的原因是Out of socket memory日志,说实话在遇到这个问题之前我并不知道有孤儿socket的存在,也是在网上查这个日志信息才知道的。产生这个日志的原因有两个:

  1. 孤儿socket太多,超出系统阈值,阈值可通过cat /proc/sys/net/ipv4/tcp_max_orphans查看。
  2. TCP缓冲区超出系统阈值,缓冲区的大小可通过cat /proc/sys/net/ipv4/tcp_mem查看。

通过另外两个日志信息基本可以判断是第一种情况了——孤儿socket太多导致的。那么孤儿socket到底是什么呢?

大部分的资料都是这么描述孤儿socket的:孤儿socket是已经没有和文件句柄绑定、但是仍然存在于内核没有被释放的socket。

这个说法相当官方,并且笼统,虽然说的并没有错误。实际用接地气的话来描述的话就是那些已经执行了close()但是状态还没有到达CLOSED状态的socket。

回忆一下TCP四次挥手的过程:

客户端执行close()函数来关闭socket,此时会发送FIN包到服务端,客户端socket的状态是FIN-WAIT-1,等到服务端ACK后状态变成FIN-WAIT-2。然后服务端也执行close(),此时socket就变成了TIME-WAIT状态,等到2MSL时间过去后才变成CLOSED。孤儿socket指的是状态在FIN-WAIT-1到TIME-WAIT之间的socket,他们已经准备释放了,但是还没有达到完全释放的条件。

2.2 分析孤儿socket状态

在确定了问题原因是孤儿socket导致的之后,排查的思路就是确定孤儿socket的状态了。

查看系统支持的最大孤儿socket数量:

查看当前socket使用状态:

# 方法1
cat /proc/net/sockstat
# 方法2
ss -s

可以看到当前环境中孤儿socket有65506个,距离超出系统负载就差一点点了。而closed和timewait状态的socket更是有10w+个之多,这种情况下内核确实承受了它这种配置不该承受的压力。

此时,下一步的排查思路就变成了为什么会有这么多socket无法完全释放了。

三、问题原因分析

当问题定位孤儿socket后,网上所有的教程都是通过放大tcp_max_orphans参数来解决,实际上是否真正能解决问题呢?调大之后会不会导致孤儿socket继续增加,是否会导致系统运行异常,这些都是有待确认的。

因为是线上环境,为了避免调整导致网络环境出现更大的异常,所以没有直接按照教程把值往上调整一倍,而是增加了5%左右。调整完成后,实际上并没有太大的效果,孤儿socket还是一直增加到了上限,dmesg也是一直打印日志,因此可以认为这种方法不可取,再往大调只会导致情况更加恶化。具体的原因还得具体再分析。

3.1 统计连接数

根据上面ss命令的结果能看到,系统处于关闭状态(执行了close()或者shutdown()之后)的socket数量很多,总量加起来接近30w个,因此首要的问题是如何定位到是什么程序产生的socket。

通过ss命令统计出所有的连接状态:

ss -ant >ss.txt 

因为连接数量很多,统计需要很长时间,所以定位到文件避免后面需要多次执行命令浪费时间。

拿回来后,分别统计出各个socket状态的数量:

imagea0fafcb19f6453e8.png

其中,最多的是FIN-WAIT-1和TIME-WAIT状态,总共有差不多17w个。它们一个是主动关闭socket的状态,一个是被动关闭socket的状态,都属于客户端socket的状态,所以问题应该出现在我们作为客户端主动发起的连接上身上。

在知晓了这一点之后,要做的应该是统计出连接的五元组信息,哪个IP、哪个端口最多,然后通过lsof命令定位到具体的程序。但是结合业务逻辑来分析,很容易就想到是我们设备上的代理程序,根本无需再统计这些信息。

因为我们设备是作为代理上网,代理程序势必要作为客户端去连接服务端,只有他才可能产生这么大规模的连接数。下一步排查的思路应该就是查它了,为什么它会产生这么多无法释放的socket。

3.2 抓包

从上面统计的状态来看,FIN-WAIT-1和TIME-WAIT状态都是处于我们已经做完了自己的事情,等待服务端响应时候的状态,我们自身出问题的可能性较小,多半是服务端除了问题导致的,所以再往下的排查思路应该是对端。

要确定是否是对端的问题,抓包就可以了,抓取wan口所有的TCP数据包,抓100w个:

tcpdump -i eth2 tcp -nnv -c 1000000 -w e2.pcap

拿到数据包后,第一步,统计所有FIN状态的数据包,在过滤器中输入:

tcp.flags.fin eq 1

为什么要统计FIN状态的数据包?

因为大量的socket都处于被关闭之后的状态,所以分析的重点就是FIN过程(即四次挥手)中那些连接。

统计出来,FIN包一共有45w个,占了所有包的45%:

这明显是一个不合理的数字,正常网络环境中不可能出现这么大比例的FIN包。随机找到一个连接追踪流分析:

左边被打马赛克的是设备的IP地址,右边的是服务端地址。服务端地址实际上是微信的服务器地址,通过应用特征分析属于微信下载小视频的流量。

很明显能看到,设备发送了FIN出去之后,并没有收到预期中的服务端回复,一直在重传等待服务端回复。直到差不多14秒之后才收到了服务端的回复信息。

到这里,就可以得到初步结论了,问题原因应该是下面二者之一:

  1. 微信服务器出了问题,回复数据包太慢了。
  2. 出口网络环境存在问题,运营商线路不稳定。

四、解决方案

解决FIN-WAIT-1和TIME-WAIT状态的方案百度有很多,基本上都是说调整fin超时时间或者其他内核参数来解决。

调整fin超时时间是调整下面这个内核参数:

理论上说这个方案是有效的,并且同时还调整了以下参数:

# 允许重用处于TIME-WAIT状态的socket
net.ipv4.tcp_tw_reuse = 1
# 开启快速回收socket
net.ipv4.tcp_tw_recycle = 1

然而实际上,调整之后,即使超时时间只有1秒,孤儿socket还是溢出了,因为内网的用户流量实在太大,即使只占用1秒对设备而言也是无法承受的。

下一步的思路只能是协调运营商和腾讯去排查了,看看为什么网络状态会如此之差!

是道德的沦丧,还是钱没给够?我猜是后者!

五、参考

The "Out of socket memory" error

一、异常处理

1.1 异常的基本用法

C语言中因为没有异常处理(只能通过返回值来判断错误)机制一直被诟病,因此C++也引入了try...catch机制,使得C++也能像java/python一样来捕获异常。

它的用法和大多数其他语言基本一致,非常简单:

try {
    throw "HelloException";
} catch (const char *msg) {
    cout << msg << endl;
}

除此之外,C++标准库中还提供了一个标准异常类exception, 内部有一个what函数可以打印异常信息:

try {
    throw std::exception();
} catch (exception &e) {
    cout << e.what() << endl;
}

执行后程序会抛出异常信息:

std::exception

不过std::exception类内部没有提供太多函数可以操作,只有基本的构造、拷贝构造以及析构函数等,自定义空间有限,很难完全依赖它打印出更详细的异常信息。因此,标准库中还提供了一些预定义的派生类来使用:

大部分的异常类都有提供自己的默认构造函数和带参构造函数,例如out_of_range异常类提供了一个char *的传入:

try {
    throw std::out_of_range("out of range");
} catch (std::out_of_range &e) {
    std::cout << e.what() << std::endl;
}

允许构造的时候带入错误信息字符串,执行what()的时候就会把这个字符串打印出来:

out of range

1.2 构造函数中的异常处理

构造函数执行初始化列表的时候,因为还没有执行到函数内部代码块,所以并不在try的捕获范围内,是无法捕获到异常的。

如若希望执行初始化列表的时候也能捕获异常,则需要在初始化列表之前加上try关键字:

my_exception() try: A(a), B(b) {}

二、自定义异常类

实际的项目中,往往会自己定义异常类,自定义异常类的方法很简单,从std::exception公有继承就可以了,内部还可以加上自己定义的成员和函数。

例如:

class my_exception : public std::exception {
public:
    int code;
    std::string msg;

    const char *what() const throw() {
        return msg.c_str();
    }

    my_exception(int code, const std::string &msg) : code(code), msg(msg) {}
};

使用方式:

try {
    throw my_exception(255, "this is a exception!");
} catch (my_exception &e) {
    cout << "ErrCode: " << e.code << ", ErrMsg: " << e.msg << endl;
    cout << e.what() << endl;
}