关于 Gunicorn + Flask 在多进程中，日志轮转的一个 BUG

V2EX = way to explore

V2EX 是一个关于分享和探索的地方

现在注册

已注册用户请登录

• 请不要在回答技术问题时复制粘贴 AI 生成的内容

语言、框架、环境

Python3.11

Gunicorn + Flask + logging

Debian 12

问题

我在开发一个小型的 Python Web 应用，选用的是 Gunicorn + Flask 的方案，日志采用了官方自带的 logging 库。

业务及其简单，但接口请求量比较大，日志记录比较多，我看到官方提供了一个logging.handlers.TimedRotatingFileHandler的日志轮转处理器，就直接用了。

但是过了一段时间，我发现了日志丢失的问题：

假设 Gunicorn 启动了 3 个 worker 进程，进程号分别是 1001 、1002 和 1003 ，一开始启动 Gunicorn 时，3 个进程的日志都能正确的写入到 app.log 中，但是一旦发生了日志轮转，最终只有一个进程（比如 1001 ）能够写入到新的 app.log 中，另外的 1002 和 1003 的日志就再也没有写入成功了。

我的猜测

我猜应该是和多进程日志处理和日志轮转相关的问题，轮转的时候，只有一个进程在切换 app.log ，其他进程找不到文件了，日志就丢失了？（我的猜测很粗糙，我不太理解原理）

当然，官方文档也提到了这点：

https://docs.python.org/zh-cn/3/howto/logging-cookbook.html#logging-to-a-single-file-from-multiple-processes

文档的建议是，使用 SocketHandler 或者 QueueHandler ，总之是单独使用一个进程处理日志。

提问

生产环境下，有什么好的解决方案？
刚刚上面的轮转日志丢失，更加具体的，本质的原理是什么？

代码

日志配置文件 logging.yaml 如下：

version:
  1

formatters:
  brief:
    format: '%(asctime)s - %(levelname)s - %(name)s - %(message)s'
  detail:
    format: '%(asctime)s - %(levelname)s - %(process)d - %(processName)s - %(name)s - %(filename)s - %(funcName)s - %(message)s'

handlers:
  console_handler:
    class: logging.StreamHandler
    level: DEBUG
    formatter: brief
    stream: ext://sys.stdout

  info_handler:
    class: logging.handlers.TimedRotatingFileHandler
    level: INFO
    formatter: detail
    filename: logs/app.log
    when: midnight
    backupCount: 2
    encoding: utf-8

  error_handler:
    class: logging.handlers.TimedRotatingFileHandler
    level: ERROR
    formatter: detail
    filename: logs/error.log
    when: midnight
    backupCount: 2
    encoding: utf-8

loggers:
  study-flask:
    level: DEBUG
    handlers: [console_handler, info_handler, error_handler]
    propagate: False

root:
  level: DEBUG
  handlers: [console_handler]

app.py 中关于日志配置的代码：

def log_config(log_config_file):
    dict_config = yaml.load(
        open(log_config_file, encoding='utf-8'),
        Loader=yaml.FullLoader
    )
    Path.mkdir(Path.cwd().joinpath("logs"), parents=True, exist_ok=True)
    logging.config.dictConfig(dict_config)


def create_app(config_mode):
    app = Flask(__name__)

    log_config('./logging.yaml')
    
    # ... 省略其他代码

第 1 条附言 · 12 小时 27 分钟前

找到类似的提问：

1. https://stackoverflow.com/questions/9975609/python-timedrotatingfilehandler-logs-are-missing

2. https://stackoverflow.com/questions/18840785/timedrotatingfilehandler-doesnt-work-fine-in-django-with-multi-instance/18843553#18843553

gunicorn

flask

日志轮转

13 条回复 • 2025-01-09 19:57:53 +08:00

dajj

12 小时 49 分钟前

多进程模式下肯定这样是不行的。考虑用其它东西，比如 redis 订阅之类的，交给另一个服务去处理日志

daxin945

12 小时 45 分钟前

我 Python 开发的时候一直用 Loguru ，推荐你试试

Koril

12 小时 43 分钟前

我自己又重新测试了下，假设 1001 对 app.log 进行轮转：

1. app.log 该名称变成 app.log.bak ，但实际上我发现 app.log.bak 的 inode 值没变

2. 1001 进程创建一个新的文件叫 app.log ，然后自己一个人把日志写入到这个新的文件里（新的 inode 值）

3. 1002 进程和 1003 进程被 1001 骗了，还在往 app.log.bak 写日志

大概，似乎，是这样子。。。

gcdsss

12 小时 42 分钟前

我踩过坑，解决方法，写一个多线程兼容的 handler 去处理

`
class MultiCompatibleTimedRotatingFileHandler(TimedRotatingFileHandler):
def doRollover(self):
if self.stream:
self.stream.close()
self.stream = None
# get the time that this sequence started at and make it a TimeTuple
currentTime = int(time.time())
dstNow = time.localtime(currentTime)[-1]
t = self.rolloverAt - self.interval
if self.utc:
timeTuple = time.gmtime(t)
else:
timeTuple = time.localtime(t)
dstThen = timeTuple[-1]
if dstNow != dstThen:
if dstNow:
addend = 3600
else:
addend = -3600
timeTuple = time.localtime(t + addend)
dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
# 兼容多进程并发 LOG_ROTATE
if not os.path.exists(dfn):
f = open(self.baseFilename, "a")
fcntl.lockf(f.fileno(), fcntl.LOCK_EX)
if not os.path.exists(dfn):
os.rename(self.baseFilename, dfn) # 释放锁释放老 log 句柄
f.close()
if self.backupCount > 0:
for s in self.getFilesToDelete():
os.remove(s)
if not self.delay:
self.stream = self._open()
newRolloverAt = self.computeRollover(currentTime)
while newRolloverAt <= currentTime:
newRolloverAt = newRolloverAt + self.interval
# If DST changes and midnight or weekly rollover, adjust for this.
if (self.when == "MIDNIGHT" or self.when.startswith("W")) and not self.utc:
dstAtRollover = time.localtime(newRolloverAt)[-1]
if dstNow != dstAtRollover:
if (
not dstNow
): # DST kicks in before next rollover, so we need to deduct an hour
addend = -3600
else: # DST bows out before next rollover, so we need to add an hour
addend = 3600
newRolloverAt += addend
self.rolloverAt = newRolloverAt
`

julyclyde

12 小时 37 分钟前

用 stream 写就行了。日志存盘那是另外的事

adoal

12 小时 33 分钟前

如果不是日志量大到惊悚，建议打到 syslog 去，用 logrotate 管理切分。比应用程序或者框架自己管理日志切分省心。

julyclyde

11 小时 49 分钟前

@adoal syslog 倒不必……大量的应用程序日志会影响调查系统级别的问题

yumenlong

11 小时 12 分钟前

import logging
from logging import getLogger, DEBUG
from concurrent_log_handler import ConcurrentRotatingFileHandler

formatter_log = logging.Formatter('%(asctime)s%(filename)s[%(lineno)d]%(funcName)s %(levelname)s %(message)s')

logger = getLogger()
logfile = os.path.abspath("log/resource.log")
rotateHandler = ConcurrentRotatingFileHandler(logfile, "a", 3000 * 1024, 50)
rotateHandler.setFormatter(formatter_log)
logger.addHandler(rotateHandler)
logger.setLevel(DEBUG)
我的也是 gunicorn 多进程,使用 ConcurrentRotatingFileHandler 正常记录多进程日志.

yumenlong

11 小时 11 分钟前

使用 ConcurrentRotatingFileHandler 可以解决多进程日志记录的问题。ConcurrentRotatingFileHandler 是 ConcurrentLogHandler 库的一部分，专门设计用于在��进程环境中安全地进行日志记录和日志轮转。

yingxiangyu

10 小时 59 分钟前

python 自带的日志库想解决这个问题很麻烦，最简单的就是不在 python 内做轮转，直接打到 std ，用类似 supervisor 之类的捕获 std 输出做轮转

yingxiangyu

10 小时 57 分钟前

现在大部分不都是用 docker 部署，直接打到 std ，用 docker 自带的日志管理实现轮转

zhangchunjiiw

8 小时 38 分钟前

import os
import time

from logging.handlers import TimedRotatingFileHandler

class SafeRotatingFileHandler(TimedRotatingFileHandler):
def __init__(self, filename, when='h', interval=1, backupCount=0, encoding=None, delay=False, utc=False):
TimedRotatingFileHandler.__init__(self, filename, when, interval, backupCount, encoding, delay, utc)

"""
多进程, 文件处理.
Override doRollover
lines commanded by "##" is changed by cc
https://www.jianshu.com/p/d615bf01e37b
"""

def doRollover(self):
"""
do a rollover; in this case, a date/time stamp is appended to the filename
when the rollover happens. However, you want the file to be named for the
start of the interval, not the current time. If there is a backup count,
then we have to get a list of matching filenames, sort them and remove
the one with the oldest suffix.

Override, 1. if dfn not exist then do rename
2. _open with "a" model
"""
if self.stream:
self.stream.close()
self.stream = None
# get the time that this sequence started at and make it a TimeTuple
currentTime = int(time.time())
dstNow = time.localtime(currentTime)[-1]
t = self.rolloverAt - self.interval
if self.utc:
timeTuple = time.gmtime(t)
else:
timeTuple = time.localtime(t)
dstThen = timeTuple[-1]
if dstNow != dstThen:
if dstNow:
addend = 3600
else:
addend = -3600
timeTuple = time.localtime(t + addend)

# 多进程, 文件处理.
dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
# if os.path.exists(dfn):
# os.remove(dfn)

# Issue 18940: A file may not have been created if delay is True.
# if os.path.exists(self.baseFilename):
if not os.path.exists(dfn) and os.path.exists(self.baseFilename):
os.rename(self.baseFilename, dfn)

if self.backupCount > 0:
for s in self.getFilesToDelete():
os.remove(s)
if not self.delay:
self.mode = "a"
self.stream = self._open()
newRolloverAt = self.computeRollover(currentTime)
while newRolloverAt <= currentTime:
newRolloverAt = newRolloverAt + self.interval
# If DST changes and midnight or weekly rollover, adjust for this.
if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
dstAtRollover = time.localtime(newRolloverAt)[-1]
if dstNow != dstAtRollover:
if not dstNow: # DST kicks in before next rollover, so we need to deduct an hour
addend = -3600
else: # DST bows out before next rollover, so we need to add an hour
addend = 3600
newRolloverAt += addend
self.rolloverAt = newRolloverAt

init:
class Logger(object):
def __init__(self):
handlers.SafeRotatingFileHandler = SafeRotatingFileHandler

yaml:
info:
class: logging.handlers.SafeRotatingFileHandler
level: INFO
formatter: console
filename: ./log/info.log
when: MIDNIGHT
interval : 1
backupCount: 7
encoding: utf8

表现就是在切分日志的时候, 会发生日志丢失

https://www.jianshu.com/p/d615bf01e37b
重写 TimedRotatingFileHandler, 之前遇到过相似问题, 希望可以帮到你.

这是 21 年左右的方式了, 现在也许会有更好的 :)

zhangchunjiiw

8 小时 37 分钟前

```py
import datetime
```