python项目 多进程日志分割

python 日志分割 （踩坑实录）

前文说到uwsgi日志分割，那个是属于uwsgi项目的运行日志，我们如果需要打印一些信息的话，如果全放在里面由于太多且多线程多进程会导致日志错乱，所以我决定再增加一个程序运行日志模块，然后踩坑开始了。

一、采用TimedRotatingFileHandler，分割when=‘D’

我一开始百度按日期分割日志，全是这个的消息，然后在本地测试了一下小时和分钟的，没什么问题，就改了改放服务器上跑了，代码如下：

def setup_log(log_name):
    # 创建logger对象。传入logger名字
    logger = logging.getLogger(log_name)
    log_path = os.path.join("../project_log", log_name)
    # 设置日志记录等级
    logger.setLevel(logging.DEBUG)
    # interval 滚动周期，
    # when="D", interval=1 表示每天生成一个文件
    # backupCount  表示日志保存个数
    file_handler = TimedRotatingFileHandler(
        filename=log_path, when="D", interval=1, backupCount=30
    )
    # filename="mylog" suffix设置，会生成文件名为mylog.2020-02-25.log
    # file_handler.suffix = "%Y-%m-%d.log"
    # extMatch是编译好正则表达式，用于匹配日志文件名后缀
    # 需要注意的是suffix和extMatch一定要匹配的上，如果不匹配，过期日志不会被删除。
    # file_handler.extMatch = re.compile(r"^\d{4}-\d{2}-\d{2}.log$")
    # 定义日志输出格式
    file_handler.setFormatter(
        logging.Formatter(
            "[%(asctime)s] [%(thread)d] [%(process)d] [%(levelname)s] - %(module)s.%(funcName)s (%(filename)s:%(lineno)d) - %(message)s"
        )
    )
    logger.addHandler(file_handler)
    return logger

然后运行了两天都发现日志没有分割成功，然后各种调整也没用，最后发现’D’选项是每次程序启动，TimedRotatingFileHandler就会在内部记录一个一天后的时间，时间到了才去分割日志，由于我们项目还在开发测试中，每天都重启几次，所以导致一直不会分割，因此要更改其他方案。

二、采用TimedRotatingFileHandler，分割when=‘MIDNIGHT’

我一开始看TimedRotatingFileHandler类的初始化代码，以为’D’选项和’MIDNIGHT’选项是相同的，其实不然，'D’是代表要过一整天才分割而’MIDNIGHT’是表示午夜0点一到就分割，显然更适用于我们的项目现况，于是兴高采烈的修改上线，第二天到了一看，裂开，分割是分割了，怎么分割出的文件内容反而今天的，昨天的日志全不见了！！！！后来一顿百度，发现是多进程导致的。我们在uwsgi.ini中设置了4个process，这样的话意味着在程序中有四个进程会在0点触发对这个文件的搬运操作，那么问题就这样产生了，如下：
看了一下 TimedRotatingFileHandler 的 doRollover 方法：

t = self.rolloverAt - self.interval
if self.utc:
    timeTuple = time.gmtime(t)
else:
    timeTuple = time.localtime(t)
dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
if os.path.exists(dfn):
    os.remove(dfn)
os.rename(self.baseFilename, dfn)

每个进程在过了 rotate 时间点之后写第一条日志的时候，都会执行这个 doRollover，然后看目标文件是否存在，存在就删除，然后再把原日志文件重命名，这样四个进程一顿操作，最前面的当然就被删除不见了，因此这个巨坑，又得换方案！

三、WatchedFileHandler + cron 定时方案

后来重新找logging库的其他FileHandler，发现了WatchedFileHandler，这这个 FileHandler 用于监视它所写入日志记录的文件。 如果文件发生变化，它会被关闭并使用文件名重新打开。（并且如果文件不存在，会创建之）
那这样的话，我们只需要改用这个，然后在写一个定时脚本来执行mv操作即可，刚刚好之前uwsgi也有一个定时分割日志的脚本，直接加在里面，搞掂！

def setup_log(log_name):
    # 创建logger对象。传入logger名字
    logger = logging.getLogger(log_name)
    log_path = os.path.join("../project_log", log_name)
    # 设置日志记录等级
    logger.setLevel(logging.DEBUG)
    file_handler = WatchedFileHandler(filename=log_path)
    file_handler.setFormatter(
        logging.Formatter(
            "[%(asctime)s] [%(thread)d] [%(process)d] [%(levelname)s] - %(module)s.%(funcName)s (%(filename)s:%(lineno)d) - %(message)s"
        )
    )
    logger.addHandler(file_handler)
    return logger

注意： [%(thread)d] [%(process)d]这两个选项对于多线程多进程定位问题时有很大的帮助，虽然日志仍然会错乱，但是定位问题时更加精准。如果想要日志不错乱，应该需要加进程锁，很麻烦而且严重影响效率，鄙人暂时才疏学浅，等以后有需要再继续学习！