句柄泄漏引发的逻辑错误

现象

后端现象是,某个配置文件 “changedir/某配置文件.json” 不定期会被删除。但是不知道是什么进程删除的。

inotify和audit监控

使用inotify监控,的确看到有删除动作,但是同样没法看到是什么进程删除了。
于是改用 audit 监控,监控出来,如下信息:

1
2
3
4
5
6
~ # ausearch -f changedir/某配置文件.json | tail
time->Thu May 31 18:00:50 2018
type=PATH msg=audit(1527760850.765:209600): item=1 name="changedir/某配置文件.json" inode=2722142 dev=08:02 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=DELETE
type=PATH msg=audit(1527760850.765:209600): item=0 name="changedir/" inode=2720150 dev=08:02 mode=040755 ouid=2 ogid=2 rdev=00:00 objtype=PARENT
type=CWD msg=audit(1527760850.765:209600): cwd="数据根目录"
type=SYSCALL msg=audit(1527760850.765:209600): arch=c000003e syscall=87 success=yes exit=0 a0=7ffa4402a460 a1=1 a2=7ffa59a22f88 a3=fffffff0 items=2 ppid=10311 pid=23637 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=1 comm="python" exe="/usr/bin/python2.7" key=(null)

可以看到,进程号pid=23637,进程名为python,删除了文件。但是,我们执行:

1
ps auxf | grep 23637

并没有发现进程。

ppid=10311为supervisor监控进程。

此外,我们发现,刚才的删除记录里面,每个十分钟就会删除一次文件:

1
2
3
4
5
6
7
8
9
10
11
12
changedir # ausearch -f changedir/某配置文件.json | grep DELETE -B1
time->Thu May 31 16:40:50 2018
type=PATH msg=audit(1527756050.211:202603): item=1 name="changedir/某配置文件.json" inode=2722145 dev=08:02 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=DELETE
--
time->Thu May 31 17:30:50 2018
type=PATH msg=audit(1527759050.608:208372): item=1 name="changedir/某配置文件.json" inode=2722145 dev=08:02 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=DELETE
--
time->Thu May 31 17:50:50 2018
type=PATH msg=audit(1527760250.733:209185): item=1 name="changedir/某配置文件.json" inode=2722145 dev=08:02 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=DELETE
--
time->Thu May 31 18:00:50 2018
type=PATH msg=audit(1527760850.765:209600): item=1 name="changedir/某配置文件.json" inode=2722142 dev=08:02 mode=0100644 ouid=0 ogid=0 rdev=00:00 objtype=DELETE

上面结束,明确了一点。

结论
有一个由supervisor拉起来的python进程,每十分钟会删除一次文件,查不到进程号的原因,目前怀疑是进程一启动便结束了。

疑问
上面”grep DELETE -B1”没有显示出来,其实我们看到,这里每10分钟执行一次DELETE操作的进程,其PID都是23637,为什么会这样?
难道每次启动都是同样的PID?还是auditd本来监控就不准确?

python代码分析

supervisor下面会拉起很多进程,逐一排查不太容易,通过搜索文件名”某配置文件.json”,我们定位到了一个python脚本:

1
2
3
4
5
6
serial_control = Serial_control("某配置文件.json")
if serial_control.verify_plat_serial() != 1:
ret = serial_control.verify_access_serial('DEV_' + client_address[0], 3)
if ret is False:
time.sleep(600)
continue

如果verify_plat_serial和verify_access_serial都判断错误,会周期性进入sleep 600s逻辑,刚好是10分钟。而且此进程也是由supervisor拉起来的,但是这个进程一直在运行,其PID并不是23637,而是23629。(注意,这两个ID之前的关联性,其PID值差别不大,应该想到是差不多时刻fork出来的。)

检测这段代码里面的判断逻辑,没什么问题,只有文件不存在的时候,才可能走到下面来,但是文件的确是存在的,单独用python调试,也是不会进入这个逻辑的。

这是最为矛盾的点:
代码是正确的,逻辑是正确的,单独调试调用函数也是正确的,pid不是它,但是从inotify删除的痕迹来看,的确是这个函数捣的鬼。

结论
这段代码嫌疑最大。

疑问
仍然是PID问题,PID不是它。

进程strace监控

我决定看看,这个 23629 进程,到底在搞什么鬼,用strace监控:

1
~ # strace -Ff -Tt -p 23629 > /var/log/s.log 2>&1

抓到一段在10分钟周期点上的系统调用痕迹:

1
2
3
4
5
6
7
8
9
10
11
[pid 23637] 18:00:50 <... select resumed> ) = 0 (Timeout) <134.921093>
[pid 23637] 18:00:50 open("xxxxx/sydays.ini", O_RDONLY) = -1 EMFILE (Too many open files) <0.000017>
[pid 23637] 18:00:50 open("xxxxx/sydays_bak.ini", O_RDONLY) = -1 EMFILE (Too many open files) <0.000017>
[pid 23637] 18:00:50 open("xxxxx/sydays.ini", O_RDONLY) = -1 EMFILE (Too many open files) <0.000017>
[pid 23637] 18:00:50 open("xxxxx/sydays_bak.ini", O_RDONLY) = -1 EMFILE (Too many open files) <0.000017>
[pid 23637] 18:00:50 stat("changedir/另外二种型号的类似配置文件.json", 0x7ffa4b4bf050) = -1 ENOENT (No such file or directory) <0.000024>
[pid 23637] 18:00:50 stat("changedir/某配置文件.json", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000024>
[pid 23637] 18:00:50 unlink("changedir/某配置文件.json") = 0 <0.000233>
[pid 23637] 18:00:50 stat("changedir/另外一种型号的类似配置文件.json", {st_mode=S_IFREG|0644, st_size=172, ...}) = 0 <0.000023>
[pid 23637] 18:00:50 unlink("changedir/另外一种型号的类似配置文件.json") = 0 <0.000094>
[pid 23637] 18:00:50 select(0, NULL, NULL, NULL, {600, 0} <unfinished ...>

结论
问题就是出在进程 23629,而23637,其实是进程的线程ID。
在LINUX下,线程ID也用PID表示,而真正的进程ID,其实是TGID,这里属于一个表达上的误导。auditd的审计结果展示的是PID,是用的gettid获取的结果,本质上是TID。

查看进程的线程,的确存在23637线程,前面的两个疑问也能很好诠释。

1
~ # pidstat -p 23629 -t 1

LINUX线程问题

Linux的NPTL(Native POSIX Threading Library)多线程,每个用户线程对应一个内核线程,是1:1的映射,相比原本实现的单线程进程,也就是在tast_struct结构体里面多加了一个tgid字段,这个字段表示线程组ID,而原本的pid含义改为线程ID的意思。
使用getpid系统调用返回的也是tast_struct中的tgid, 而tast_struct中的pid则由gettid系统调用返回。
tgid等于pid的线程,就是线程组长,也就是我们平时看到的进程ID。

1
2
3
~/w # ps auxf | grep receive_daemon
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 34305 0.0 0.0 2578000 30936 pts/3 Sl+ 00:43 0:05 | \_ python /aaaa/bin/LinkDEV/receive_daemon.py.bak

查看多线程:

1
2
3
4
5
6
7
~/w # ps -Laf | receive_daemon
UID PID PPID LWP C NLWP STIME TTY TIME CMD
root 34305 20133 34305 0 34 00:43 pts/3 00:00:00 python /aaaa/bin/LinkDEV/receive_daemon.py.bak
root 34305 20133 34351 0 34 00:43 pts/3 00:00:00 python /aaaa/bin/LinkDEV/receive_daemon.py.bak
root 34305 20133 34352 0 34 00:43 pts/3 00:00:00 python /aaaa/bin/LinkDEV/receive_daemon.py.bak
root 34305 20133 34353 0 34 00:43 pts/3 00:00:00 python /aaaa/bin/LinkDEV/receive_daemon.py.bak
root 34305 20133 34354 0 34 00:43 pts/3 00:00:00 python /aaaa/bin/LinkDEV/receive_daemon.py.bak

通过上面的strace日志,还可以看出一个重要结论:

结论
打开文件返回的错误是 -1 EMFILE (Too many open files) 。
再明确不过的提示,表示进程句柄超限了,确认:

1
2
3
> ~ # lh /proc/23629/fd | wc -l
> 65537
>

而且,此通过句柄超限,可以印证为什么会走到上面删除文件的逻辑:

1
2
3
4
5
6
7
8
9
10
11
12
def verify_plat_serial(self):
ret = 1
result = sipserial.verifyModelSerial(1)
if result == -2:
try:
for path in dev_list:
if os.path.isfile(path):
os.remove(path)
# 这里日志没有打印出来,是句柄超限?还是daemon标记设置后关闭了所有继承句柄,需要重新初始化syslog?反正日志是没有打印出来。
except:
return -1
return ret

1
2
3
4
5
6
7
8
9
int verifyModelSerial(int model, int subModel, int subModelCount )
{
...
ReadFile(CONF_SERIAL_PATH,ConfSerialIterator,(void*)serial);
if (strlen(serial) == 0)
{
free(decrypts); //这里读取不到数据,上面函数收到了-2的返回值
return -2;
}

代码移除法

通过proc可以看到,泄漏的句柄属于socket:

1
2
3
4
5
SIS3.0.2.1 ~/w # ls -lh /proc/$(psp receive_daemon.py.bak | awk '{print $1}')/fd
lrwx------ 1 root root 64 May 27 00:43 13 -> socket:[146446952]
lrwx------ 1 root root 64 May 27 00:49 14 -> socket:[146474097]
lrwx------ 1 root root 64 May 27 00:49 15 -> socket:[146474098]
...

而netstat里面看不到是谁连接的socket,这是比较不解的地方。代码里面有两个地方使用了socket,一是使用了mongo连接,检查逻辑,没什么问题。二是使用了UDPServer监听端口:

1
2
3
4
5
6
serv = UDPServer(LISTEN_SOCKET, UserInfoToMongoHandler)
for n in range(NWORKERS):
t = Thread(target=serv.serve_forever)
t.daemon = True
t.start()
serv.serve_forever()

现在怀疑UDPServer用法是否有误,撸了一遍UDPServer源码,没有发现问题。
又写了一个客户端,来发送UDP包,发现,每发送一次UDP包,UDPServer这端的进程,会增加两个socket句柄。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
import socket
import sys
HOST, PORT = "127.0.0.1", LISTEN_SOCKET
data = " ".join(sys.argv[1:])
# SOCK_DGRAM is the socket type to use for UDP sockets
sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
# As you can see, there is no connect() call; UDP has no connections.
# Instead, data is directly sent to the recipient via sendto().
sock.sendto(data + "\n", (HOST, PORT))
received = sock.recv(1024)
print "Sent: {}".format(data)
print "Received: {}".format(received)

又将官方的UDPServer示例代码拷贝下来,执行,同样的客户端发给UDPServer,没有句柄泄漏。

现在怀疑是UDPServer和多线程嵌套后,有BUG,于是在官方示例代码基础上,加了多线程,也没有句柄泄漏。

目前看,只能用笨方法,代码移除法,一点一点验证,好在是Python代码,移除代码执行非常方便。没几下,便定位到了一段序列号验证函数。
有它的时候,便会句柄泄漏,没它的时候,正常。

单独对这段代码做strace,发现:

1
2
3
4
[pid 34351] 00:45:25 socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 14 <0.000017>
[pid 34351] 00:45:25 ioctl(14, SIOCGIFHWADDR, {ifr_name="ethX", ifr_hwaddr=aa:aa:aa:aa:aa:aa}) = 0 <0.000010>
[pid 34351] 00:45:25 socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 15 <0.000012>
[pid 34351] 00:45:25 ioctl(15, SIOCGIFHWADDR, {ifr_name="ethY", ifr_hwaddr=bb:bb:bb:bb:bb:bb}) = 0 <0.000012>

这段序列号验证函数是C代码书写,外层调用没什么问题,后来定位到一公共库,公共库是公共技术部提供的动态库,其中一个函数,获取网卡信息没有关闭句柄:
没关闭句柄汇编