上个月用python的gevent协程库写了一个tcp服务。日志库使用python标准日志库logging。一个月后，发现一个偶发的bug。这个bug发生时，用python的标准日志库自带的FileHandler写的日志会发往socket占用的文件描述符fd。结果就是，客户端收到了本要打印到磁盘上的日志。花了不少时间定位排查这个bug，仍然没有结果。我开始怀疑是gevent协程库和python的标准日志库logging有冲突。协程库会错误的把logging打开的文件描述符fd关闭并分配给新创建的socket，于是日志就打印到socket占用的fd了。
后来，写了一个检测脚本用来监控这个情况发生的概率。该脚本每分钟会检查进程占用的所有fd，一但发现用来打印本地日志的文件fd不见了，就重启服务进程。核心代码如下:
lsof -p $pid | grep -q ${log_file_name} if [ $? != 0 ] then # 报警代码 ... fi 发现bug发生的频率大概是一个星期一次。但这毕竟根本上解决不了问题啊，又找不到bug的原因，怎么办？
那就自定义一个File Handler吧！ 决定自定义一个File Handler，这个File Handler工作在另外一个单独的进程，这样无论如何日志用的fd都不会跟主进程的各种socket用的fd冲突了吧。
代码如下，主要用到的技术进程通讯和用python的__getattribute__魔法把截获类实例的方法调用。这样，只需要把旧的代码中的File Handler(我用了TimedRotatingFileHandler)换成自定义的Handler Class，所有其他旧代码都无需改动。
#!/usr/bin/env python3 ''' created by kamuszhou*AT*tencent.com, zausiu*AT*gmail.com http://ykyi.net Nov 20, 2018 ''' import logging import logging.handlers from functools import partial from multiprocessing import Process, Queue class MySpecialHandler(logging.StreamHandler): def __init__(self, *args, **kargs): self._q = Queue() self._p = Process(target=MySpecialHandler.__run, args=(self._q,)) self._p.start() self._q.put(('__init__', args, kargs)) def join(self): self._p.join() def __run(q): handler = None while True: # op, params = q.get() method, args, kwargs = q.get() if method == '__init__': handler = logging.handlers.TimedRotatingFileHandler(*args, **kwargs) else: # 主进程的日志调用实际上被转到这里 getattr(handler, method)(*args, **kwargs) def __proxy(self, name, *args, **kwargs): # 把调用的方法名和方法参数通过Queue传到专门的日志进程。 self._q.put((name, args, kwargs)) fun = logging.StreamHandler.__getattribute__(self, name) # print('call method: ', name, args, kwargs) # 如果是setLevel函数，再调用一次父类的方法 if name in {'setLevel'}: return fun(*args, **kwargs) def __getattribute__(self, name): ''' Hook大法！截获所有方法 ''' attr = logging.StreamHandler.__getattribute__(self, name) if hasattr(attr, '__call__') and name not in {'join', 'emit'}: return partial(MySpecialHandler.__proxy, self, name) else: return attr if __name__ == '__main__': handler = MySpecialHandler('/data/tmp/ttt.log', when='D', interval=1, backupCount=90) handler.setLevel(logging.DEBUG) formatter = logging.Formatter('%(asctime)s: %(levelname)s %(message)s') handler.setFormatter(formatter) logger = logging.getLogger(__name__) logger.propagate = False # Don't propagate the logging to ROOT logger.setLevel(logging.DEBUG) logger.addHandler(handler) logger.debug('debug testtttttttt') logger.info('info testtttttttttt') logger.warn('warn testtttttttttt') logger.error('error testtttttttt') logger.critical('critical testttttt') handler.join() 这里自定义的日志进程类只是一个很粗糙的实现，一但跑起来，只能手动杀进程。反正我的使用场景是一个服务。所以，我也懒得加‘优雅的退出代码’。
...