句柄泄漏引发的逻辑错误

发表于 |

现象

后端现象是，某个配置文件 “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代码书写，外层调用没什么问题，后来定位到一公共库，公共库是公共技术部提供的动态库，其中一个函数，获取网卡信息没有关闭句柄：
没关闭句柄汇编