loguru多进程切分日志异常分析

测试代码

# main.py
from mylog import log
import multiprocessing
import time, os, sys, datetime


def worker():
    while True:
        time.sleep(0.1)
        log.info(str(os.getpid()) + " --- " + "Logging...")
        #print(str(id(log)) + "\n")


if __name__ == "__main__":
    print(os.getpid())
    log.info("davy test.!")
    #print(str(id(log)))
    #fname = time.strftime('%Y%m%d%H%M', time.localtime())
    #print(fname)
    #sys.exit(0)

    multiprocessing.set_start_method("spawn")
    processes = [multiprocessing.Process(target=worker) for _ in range(4)]

    for p in processes:
        p.start()

    for p in processes:
        p.join()

mylog.py

import logging.handlers

from loguru import logger

import concurrenthandler


class mylog:
    def __new__(self):
        logger.remove(handler_id=None)
        log = logger
        # log.add(concurrenthandler.TimedRotatingFileHandler_MP("davy.log", 'D', 1, 0) )

        log.add("./logs/davy.log",
                rotation="10 KB", enqueue=False
                )

        return log

log = mylog()

主要调整main.py里的multiprocessing.set_start_method = fork / spawn (这俩其实差不多，不过 当Loguru的equeue=True的时候，不能显式设置这个值了，不然会报错。

loguru日志库的_file_sink.py里面 Class FileSink中的write方法

if self._rotation_function is not None and self._rotation_function(message, self._file):
            print(os.getpid(), id(self._file),str(self._file.tell() + len(message)), self._file.name)
            self._terminate_file(is_rotating=True)
            print(self, self._file.fileno(), self._file.tell(), " rotate file end....\n")

测试 equeue=False时候， 每个子进程在log.info的时候，都会执行这个方法写入文件，由于子进程的文件描述符是从父进程拷贝过来的，所以，都会写入davy.log，是没有问题的。

当写满10KB的时候， self._rotation_function方法校验，就会返回True，_rotation_function = Rotation.rotation_size这个方法（因为loguru.add的时候，rotation设置的是 10KB，在初始化的时候，会选取这个方法 ，见 _make_rotation_function 函数的逻辑， 也在_file_sink.py中），然后执行 _terminate_file,(这里面会调用 os.rename davy.log --> davy.2022.01.01.11.12.333.log这中格式的备份文件，然后重新open davy.log,复制给self._file。

这里就会出现问题了，即便是假设日志写入不频繁，每个子进程都可以完美的不同时间执行log.info，我们看看会发生什么。（这里很容易测试， 在 write方法首尾加上文件锁，就可以保证进程不会并发执行了）

# set_start_method = spawn

3878
3884 139935998440944 10072 /home/davy/PycharmProjects/logurudemo/logs/davy.log
qiefen le wenjian -- 0
<loguru._file_sink.FileSink object at 0x7f4563f4c340> 4 0 rotate file end....

3886 140586464327152 10072 /home/davy/PycharmProjects/logurudemo/logs/davy.log
qiefen le wenjian -- 0
<loguru._file_sink.FileSink object at 0x7fdcd6be8340> 4 0 rotate file end....

3887 139707968435696 10072 /home/davy/PycharmProjects/logurudemo/logs/davy.log
qiefen le wenjian -- 0
<loguru._file_sink.FileSink object at 0x7f104c4f0340> 4 0 rotate file end....

3885 140430168053232 10072 /home/davy/PycharmProjects/logurudemo/logs/davy.log
qiefen le wenjian -- 0
<loguru._file_sink.FileSink object at 0x7fb872c2a340> 4 0 rotate file end....

# set_start_menthod = fork

3927
3928 140395167977184 10038 /home/davy/PycharmProjects/logurudemo/logs/davy.log
qiefen le wenjian -- 0
<loguru._file_sink.FileSink object at 0x7fb04c14aeb0> 3 0 rotate file end....

3929 140395167977184 10038 /home/davy/PycharmProjects/logurudemo/logs/davy.log
qiefen le wenjian -- 0
<loguru._file_sink.FileSink object at 0x7fb04c14aeb0> 3 0 rotate file end....

3931 140395167977184 10038 /home/davy/PycharmProjects/logurudemo/logs/davy.log
qiefen le wenjian -- 0
<loguru._file_sink.FileSink object at 0x7fb04c14aeb0> 3 0 rotate file end....

3930 140395167977184 10038 /home/davy/PycharmProjects/logurudemo/logs/davy.log
qiefen le wenjian -- 0
<loguru._file_sink.FileSink object at 0x7fb04c14aeb0> 3 0 rotate file end....

上面是设置 spawn和fork 后，输出的日志，就明显可以看出fork和 spawn的区别了，fork明显file和 filesink实例的地址各个子进程都一样（这里的一样没什么关系，反正不同进程映射的物理地址也不一样，只不过明显能看出来，完全从父进程COPY过来而已，这里fork和spawn都会导致切分混乱，生成4个日志文件。），这里不管地址是否一样，有一点是相同的，就是每个子进程打开的文件描述符，都对应着davy.log，是不会变的。

从代码里，就能理解了，当第一个进程检查size超标，然后切分日志，这里  执行os.rename(str,str)，这里就会出现问题了，因为 rename只是改了名，i_node是不会变的，也就是说，只要打开过这个文件的文件描述符，依然是指向了改名后的文件。然后， Open新的davy.log，复制给 self._file,这样子，这个进程的_file，就可以继续写入空白的davy.log了。

而其他进程的self._file,跟进程1没有任何关系（即便是虚拟地址一样，都没有任何关系，fork由 copy_on_write功能，只要有修改，其实都会跟父进程割离了）

假设这里进程1完成了最后的self._file.write(message)后，第二个进程进来了，由于进程2的 self._file的文件描述符还是指向了原来的davy.log，所以，检查文件大于10K，依然会执行一边切分文件的动作（但是 os.rename却是把 进程1生成的davy.log重命名成新的备份文件了），进程3/4，也是一样的道理，所以这种情况，一定会发生切分混乱的。

同理，即便是用gunicorn之类的启动flask或者fastapi之类的程序，肯定也是一样的效果。

再说  enqueue=True的时候，代码里，其实是靠multiprocessing.SimpleQueue 来实现的日志的读取写入的。

设置了enqueue=True，就不能设置set_start_method了，不然报错。（有说multiprocessing模式fork）

调试观察，就能知道，其实只是父进程提前启动了一个线程去监听这个queue，而子进程在log.info的时候，只是向这个queue里发送数据，然后由主进程做实际的write动作，那肯定不会导致切分异常的。

但是这种情况，如果我启动两个python进程去执行测试用例，那跟第一种情况，就没什么区别了，而测试一下，结果的确如此，毕竟 multiprocessing的queue是通过内核queue或者pipe来实现的，所以只有父子进程可以通信，（命名管道之类的除外，那是别的进程间通讯方式了，loguru的实现，保证不了无关系进程之间的进程安全的）。

以上的理解

这时候，去理解uvicorn之类的，在启动fastapi的时候， 在 loguru _handler.py里的初始化那里

# _hanlder.py 大概 85行左右
if self._enqueue:
            print(os.getpid(), " init equeue = true")
            self._queue = multiprocessing.SimpleQueue()
            self._confirmation_event = multiprocessing.Event()
            self._confirmation_lock = multiprocessing.Lock()
            self._owner_process_pid = os.getpid()
            self._thread = Thread(
                target=self._queued_writer, daemon=True, name="loguru-writer-%d" % self._id
            )
            self._thread.start()

执行 uvicorn fastdemo:app --workers=4 ，就能看到  print 打印了4次，跟真实的4个不同的进程初始化了loguru一样，multiprocess.simplequeue是保证不了安全性的，都是个干个的，所以日志文件，在切分的时候，依然是执行了4此切分。

 

方法一：

如果要一定要保证切分的安全性，可以采用别人写好的 logging.handlers，（应该有一个比较常用的并行concurrent_log的库好像），不过loguru如果通过这种添加handlers的方式去执行的话，就没啥意义了，切分动作，都委托给了handler了，自己也不能设置rotation,只能在引用的别人的handlers里设置，多此一举的感觉，nb_log里有提到那几个库。

 

方法二：

不考虑性能，直接在 _file_sink.py的write里，首尾不但加文件锁， 而且还要  close --》 open 一下 log文件，保证每次检查的文件，都是重命名后的那个新文件，而不是自己一直保持的文件描述符对应的那个log文件。不过这种性能的确是效率颇低，不但有文件锁，还会频繁执行 close和open操作，针对不频繁的日志场景还凑合。

 

方法三：

   可以看看nb_log如何实现的，不太想研究这个了，有时间再看吧。