今天用python写一个监控日志的demo遇到一个很奇怪的现象。demo的功能是：用tail -f监控日志文件的新内容，直到匹配到标识符字符串为止，若在一定时间内没有监听到标识符字符串，则脚本结束，打印服务启动失败的信息。
demo代码如下：
# encoding: utf-8
# mo3.py
import time
import subprocess
import threading
def killP(p, sec):
'''
kill掉p进程
:param p: 进程的实例
:param sec: 超时时间
:return:
'''
stoptime = time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(time.time() + sec))
while True:
thistime = time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(time.time()))
if thistime >= stoptime:
# 终止子进程
print('服务启动失败!!!')
p.terminate()
print("killP: " + str(p.returncode))
break
def monitorLog(p):
'''
日志监控(demo)
:param p: 进程的实例
:return:
'''
print("monitorLog")
while True:
print(p.stdout.readline())
if p.returncode is not None:
print("killed")
break
print("quit monitorLog")
if __name__ == "__main__":
p = subprocess.Popen('tail -0f log.txt', stdout=subprocess.PIPE, stderr=subprocess.PIPE, shell=True)
print("pid: " + str(p.pid))
p1 = threading.Thread(target=killP, args=(p, 30))
p2 = threading.Thread(target=monitorLog, args=(p,))
threads = []
threads.append(p1)
threads.append(p2)
for t in threads:
t.start()
for t in threads:
t.join()
脚本中新开一个进程p，执行tail -f命令读取log.txt。p1和p2是两个并发的线程，p1做日志内容监控（这里仅为demo，详细监控逻辑没写），p2做超时结束，这里设置30s内没有监控到匹配内容，就强制杀进程p结束脚本。
启动脚本，看下父子进程的关系：
57912 ? Ss 0:00 \_ sshd: ivanli [priv]
57973 ? S 0:01 \_ sshd: ivanli@pts/6
57974 pts/6 Ss 0:01 \_ -bash
59367 pts/6 Sl+ 0:01 \_ python mo3.py
59368 pts/6 S+ 0:00 \_ /bin/sh -c tail -0f log.txt
59370 pts/6 S+ 0:00 \_ tail -0f log.txt
59368即为进程p，59370 tail -0f log.txt为p的子进程。
然后就遇到了个问题，若log.txt的内容没有更新，这时启动脚本去监听日志，代码就卡死在print(p.stdout.readline())了，即tail -0f没有返回值回来。而且在killP中，p进程杀掉后的返回码还是None，表明p进程没有被干掉。
ivanli@ubuntu:~/myown/test/shell$ python mo3.py
pid: 59368
monitorLog
服务启动失败!!!
killP: None
这时再看父子进程关系，奇怪的现象发生了：
57912 ? Ss 0:00 \_ sshd: ivanli [priv]
57973 ? S 0:01 \_ sshd: ivanli@pts/6
57974 pts/6 Ss 0:01 \_ -bash
59367 pts/6 Sl+ 0:29 \_ python mo3.py
59368 pts/6 Z+ 0:00 \_ [sh] <defunct>
1214 ? Ss 0:05 cron
1226 ? Ss 16:53 /usr/sbin/irqbalance
1238 ? Ssl 0:03 whoopsie
1302 ? Ss 0:00 /usr/sbin/cups-browsed
1310 ? Ss 0:35 /usr/sbin/kerneloops
1317 ? Ssl 58:25 /usr/sbin/mysqld
1379 tty1 Ss 0:00 /bin/login --
2390 tty1 S+ 0:00 \_ -bash
1555 ? Ss 0:00 acpid -c /etc/acpi/events -s /var/run/acpid.socket
1570 ? Ssl 0:00 /usr/sbin/vmware-vmblock-fuse -o subtype=vmware-vmblock,default_permissions,allow_other /
1588 ? Sl 48:55 /usr/sbin/vmtoolsd
1884 ? Ssl 110:32 /usr/bin/dockerd --raw-logs
1902 ? Ssl 50:33 \_ docker-containerd -l unix:///var/run/docker/libcontainerd/docker-containerd.sock --me
49422 ? Sl 0:01 | \_ docker-containerd-shim e84dc455581d8be490b5ebb63b1fcbb6675b1e14888a7eebf36caf7833
49439 ? Ssl 15:13 | \_ /docker-java-home/jre/bin/java -Djava.util.logging.config.file=/usr/local/tom
49416 ? Sl 0:00 \_ /usr/bin/docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 8111 -container-ip 172.1
2502 ? Sl 0:00 /usr/lib/colord/colord
12297 ? Ss 0:00 /usr/sbin/cupsd -f
12335 ? Ss 1:06 tpvmlpd2
59370 pts/6 S+ 0:00 tail -0f log.txt
59368居然变为[sh] <defunct>了！另外59370 tail -0f log.txt依然还在！
说明进程p没有被干掉，手动强制干掉这个奇怪的[sh] <defunct>，发现居然没法手动kill掉。好奇怪，然后网上搜了下，得知[sh] <defunct>为僵尸进程，无法kill掉，出现僵尸进程的原因一般如下：
- 父进程在子进程先退出
- 父进程没有处理子进程的退出信号
再结合前后的ps看，59368是59370的父进程，在代码里terminate了59368，即父进程先退出了，所以导致59368变成了僵尸进程，59370变成孤魂野鬼，依然游荡，而且没有爹了。这也导致p.returncode一直为None，而且由于59368 tail -0f log.txt一直在跑，且log.txt没有更新，所以就一直卡在tail命令中，导致代码一直卡死在print(p.stdout.readline())。而且这时你手动kill掉59368的爹59367，孤魂野鬼59370依然在运行，占用pid。
这个问题困扰了自己近一天的时间，这下才明白问题出在哪。解决方法是：
在kill p进程之前，先干掉他的儿子tail -0f log.txt进程，然后再干掉p。这样就不会出现僵尸进程，并且也实现了超时结束模块的功能。改进后的demo代码如下：
# encoding: utf-8
# mo3_1.py
import time
import subprocess
import threading
def killP(p, sec):
'''
kill掉p进程
:param p: 进程的实例
:param sec: 超时时间
:return:
'''
stoptime = time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(time.time() + sec))
while True:
thistime = time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(time.time()))
if thistime >= stoptime:
subp = subprocess.Popen("ps -ef | grep tail | grep -v grep | awk '{print $2}' | xargs kill -9",
stdout=subprocess.PIPE, stderr=subprocess.PIPE, shell=True) # 干掉p的子进程
print('服务启动失败!!!')
p.terminate() # 干掉p
print("killP: " + str(p.returncode))
break
def monitorLog(p):
'''
日志监控(demo)
:param p: 进程的实例
:return:
'''
print("monitorLog")
while True:
p.wait()
print(p.returncode)
print(p.stdout.readline())
if p.returncode is not None:
print("killed")
break
print("quit monitorLog")
if __name__ == "__main__":
p = subprocess.Popen('tail -0f log.txt', stdout=subprocess.PIPE, stderr=subprocess.PIPE, shell=True)
print("pid: " + str(p.pid))
p1 = threading.Thread(target=killP, args=(p, 30))
p2 = threading.Thread(target=monitorLog, args=(p,))
threads = []
threads.append(p1)
threads.append(p2)
for t in threads:
t.start()
for t in threads:
t.join()
在killP中，若超时时间到，先干掉p的子进程，即干掉tail -0f log.txt。然后再干掉p，这样p.returncode就不为None了。monitorLog中的while也可以break了。
网友评论