Python Flask + Gunicorn + Docker 的日志输出设置

狄心水

2023-12-01

我们一个项目使用了 Python Flask 框架来实现 Web 服务，之前的日志输出一直有问题。而从项目需求、运行维护出发，正确的日志输出对使用者来说都是非常重要的。

这里完整的整理了从开发 Flask 时的日志设置，到生产环境使用 Gunicorn 运行 Flask 的日志设置以及使用 Docker 容器化部署的日志输出的全部细节。

普通 Flask 日志设置

Flask 本身使用 Python 的 logging 模块来实现日志记录、输出，以一个最简单的 Flask 应用代码为例：

import logging
from flask import Flask, jsonify

app = Flask(__name__)

@app.route('/')
def default_route():
    """Default route"""
    app.logger.debug('this is a DEBUG message')
    app.logger.info('this is an INFO message')
    app.logger.warning('this is a WARNING message')
    app.logger.error('this is an ERROR message')
    app.logger.critical('this is a CRITICAL message')
    return jsonify('hello world')

if __name__ == '__main__':
    app.run(host='0.0.0.0', port=8000, debug=True)

运行程序：

$ pip install flask

$ python app.py

 * Serving Flask app "app" (lazy loading)
 * Environment: production
   WARNING: This is a development server. Do not use it in a production deployment.
   Use a production WSGI server instead.
 * Debug mode: on
 * Running on http://0.0.0.0:8000/ (Press CTRL+C to quit)
 * Restarting with stat
 * Debugger is active!
 * Debugger PIN: 265-991-043

访问 http://localhost:8000/ ，程序会在命令行窗口输出：

[2022-12-21 15:46:29,113] DEBUG in app: this is a DEBUG message
[2022-12-21 15:46:29,113] INFO in app: this is an INFO message
[2022-12-21 15:46:29,113] WARNING in app: this is a WARNING message
[2022-12-21 15:46:29,113] ERROR in app: this is an ERROR message
[2022-12-21 15:46:29,113] CRITICAL in app: this is a CRITICAL message
127.0.0.1 - - [21/Dec/2022 15:46:29] "GET / HTTP/1.1" 200 -

输出日志文件

我们可以使用 logging 模块的不同输出处理器（Handler）来实现标准输出、文件输出或邮件提醒。例如添加日志文件：

import logging
from flask import Flask, jsonify

app = Flask(__name__)

@app.route('/')
def default_route():
    """Default route"""
    app.logger.debug('this is a DEBUG message')
    app.logger.info('this is an INFO message')
    app.logger.warning('this is a WARNING message')
    app.logger.error('this is an ERROR message')
    app.logger.critical('this is a CRITICAL message')
    return jsonify('hello world')

if __name__ == '__main__':
    # Define log level and log file
    app.debug = True
    handler = logging.FileHandler('flask.log')
    app.logger.addHandler(handler)

    app.run(host='0.0.0.0', port=8000, debug=True)

访问 http://localhost:8000 ，我们可以看到在当前目录下生成了 flask.log 日志文件：

$ ls
app.py  flask.log
$ cat flask.log
this is a DEBUG message
this is an INFO message
this is a WARNING message
this is an ERROR message
this is a CRITICAL message

按天分割、调整格式

我们常见的日志文件一般按天分割，这样方便查找。另外日志里还需要记录一些必须的时间等值：

import logging
from flask import Flask, jsonify
from logging.handlers import TimedRotatingFileHandler

app = Flask(__name__)

@app.route('/')
def default_route():
    """Default route"""
    app.logger.debug('this is a DEBUG message')
    app.logger.info('this is an INFO message')
    app.logger.warning('this is a WARNING message')
    app.logger.error('this is an ERROR message')
    app.logger.critical('this is a CRITICAL message')
    return jsonify('hello world')

if __name__ == '__main__':
    app.debug = True
    formatter = logging.Formatter(
        "[%(asctime)s][%(filename)s:%(lineno)d][%(levelname)s][%(thread)d] - %(message)s")
    handler = TimedRotatingFileHandler(
        "flask.log", when="D", interval=1, backupCount=30,
        encoding="UTF-8", delay=False, utc=False)

    handler.setFormatter(formatter)
    app.logger.addHandler(handler)

    app.run(host='0.0.0.0', port=8000, debug=True)

TimedRotatingFileHandler 的参数设置：

when=D：按天进行切分，还可以按秒（S）、分钟（M）、小时（H）、星期时间（‘W0’-‘W6’，W0=周一，此时 interval 不起作用）、半夜时间（midnight）
interval=1：每1天切分，这个值根据上面的 when 来确定单位
backupCount=30：保留30天的日志
encoding=UTF-8: 使用 UTF-8 的编码
delay=False：如果为 True，文件打开会被推迟到第一次调用 emit()
utc=False：使用当前系统时间而非 UTC 时间

Formatter 的格式可以参考 https://docs.python.org/2/library/logging.html#logrecord-attributes

再次访问 http://localhost:8000 ，日志文件输出变成了：

[2022-12-21 16:17:05,825][app.py:10][DEBUG][139836122048256] - this is a DEBUG message
[2022-12-21 16:17:05,826][app.py:11][INFO][139836122048256] - this is an INFO message
[2022-12-21 16:17:05,826][app.py:12][WARNING][139836122048256] - this is a WARNING message
[2022-12-21 16:17:05,827][app.py:13][ERROR][139836122048256] - this is an ERROR message
[2022-12-21 16:17:05,827][app.py:14][CRITICAL][139836122048256] - this is a CRITICAL message

引入蓝图 BluePrint

稍微复杂一点的 Flask 程序，可能会使用 BluePrint 来对不同功能模块进行拆分。而使用 BluePrint 后的 Flask 程序，其日志的调用方式有少许变化。

.
├── api
│   └── test.py
├── app.py
└── flask.log

我们在当前项目目录下新建一个 api 目录，然后在其下创建 test.py ，这里我们创建了一个名为 test 的 Blueprint 对象，并且添加了路由 /test 到其下的 show() 方法。这里要获得 Flask 的应用对象，就需要用它的 current_app 来实现对 app 的引用了。

from flask import Blueprint, jsonify, current_app

test = Blueprint('test', __name__)

@test.route('/test', methods=('GET', 'POST'))
def show():
    current_app.logger.debug('Test DEBUG message')
    current_app.logger.info('Test INFO message')
    current_app.logger.warning('Test WARNING message')
    current_app.logger.error('Test ERROR message')
    current_app.logger.critical('Test CRITICAL message')
    return jsonify('Show test')

然后对 app.py 进行修改，把上面的 test 蓝图注册到 app 对象里，并且添加路由前缀 /api 。

import logging

from flask import Flask, jsonify
from logging.handlers import TimedRotatingFileHandler

app = Flask(__name__)

from api.test import test
app.register_blueprint(test, url_prefix='/api')

@app.route('/')
def default_route():
    """Default route"""
    app.logger.debug('this is a DEBUG message')
    app.logger.info('this is an INFO message')
    app.logger.warning('this is a WARNING message')
    app.logger.error('this is an ERROR message')
    app.logger.critical('this is a CRITICAL message')
    return jsonify('hello world')

if __name__ == '__main__':
    app.debug = True
    formatter = logging.Formatter(
        "[%(asctime)s][%(filename)s:%(lineno)d][%(levelname)s][%(thread)d] - %(message)s")
    handler = TimedRotatingFileHandler(
        "flask.log", when="D", interval=1, backupCount=30,
        encoding="UTF-8", delay=False, utc=False)

    handler.setFormatter(formatter)
    app.logger.addHandler(handler)

    app.run(host='0.0.0.0', port=8000, debug=True)

我们分别访问 http://localhost:8000 和 http://localhost:8000/api/test ，可以看到返回正确的结果，日志文件变成了：

[2022-12-21 17:30:34,627][app.py:14][DEBUG][140282256979712] - this is a DEBUG message
[2022-12-21 17:30:34,628][app.py:15][INFO][140282256979712] - this is an INFO message
[2022-12-21 17:30:34,628][app.py:16][WARNING][140282256979712] - this is a WARNING message
[2022-12-21 17:30:34,629][app.py:17][ERROR][140282256979712] - this is an ERROR message
[2022-12-21 17:30:34,629][app.py:18][CRITICAL][140282256979712] - this is a CRITICAL message
[2022-12-21 17:30:50,946][test.py:7][DEBUG][140282256979712] - Test DEBUG message
[2022-12-21 17:30:50,947][test.py:8][INFO][140282256979712] - Test INFO message
[2022-12-21 17:30:50,947][test.py:9][WARNING][140282256979712] - Test WARNING message
[2022-12-21 17:30:50,947][test.py:10][ERROR][140282256979712] - Test ERROR message
[2022-12-21 17:30:50,949][test.py:11][CRITICAL][140282256979712] - Test CRITICAL message

至此，Flask 的日志一切都运转良好。然后我们在生产服务器上部署的时候，现在常常会使用 Gunicorn 来运行，这时候的日志输出就有问题了，日志文件没有内容写入。

使用 Gunicorn 运行的 Flask 日志设置

Gunicorn 有自己的日志记录器，它通过本身的机制控制日志级别。我们只能通过配置 Gunicorn 的日志设定，来实现我们的需求。同时，需要对上面例子应用的日志处理器设置进行调整。

修改 app.py，注意我们添加的 if __name__ != '__main__' 这部分，就是在 Gunicorn 运行时，让 Flask 使用它的日志处理器。

import logging

from flask import Flask, jsonify
from logging.handlers import TimedRotatingFileHandler

app = Flask(__name__)

from api.test import test
app.register_blueprint(test, url_prefix='/api')

@app.route('/')
def default_route():
    """Default route"""
    app.logger.debug('this is a DEBUG message')
    app.logger.info('this is an INFO message')
    app.logger.warning('this is a WARNING message')
    app.logger.error('this is an ERROR message')
    app.logger.critical('this is a CRITICAL message')
    return jsonify('hello world')

# make app to use gunicorn logger handler
if __name__ != '__main__':
    gunicorn_logger = logging.getLogger('gunicorn.error')
    app.logger.handlers = gunicorn_logger.handlers
    app.logger.setLevel(gunicorn_logger.level)

if __name__ == '__main__':
    app.debug = True
    formatter = logging.Formatter(
        "[%(asctime)s][%(filename)s:%(lineno)d][%(levelname)s][%(thread)d] - %(message)s")
    handler = TimedRotatingFileHandler(
        "flask.log", when="D", interval=1, backupCount=30,
        encoding="UTF-8", delay=False, utc=False)

    handler.setFormatter(formatter)
    app.logger.addHandler(handler)

    app.run(host='0.0.0.0', port=8000, debug=True)

参考 Gunicorn 日志设置，我们在启动 Gunicorn 时可以使用下面的命令行：

# 创建日志目录
$ mkdir -p /var/log/gunicorn/

# 赋予日志目录当前用户权限
$ chown tattoo:tattoo /var/log/gunicorn/

# 运行 gunicorn
$ gunicorn -w 2 \
        -b 0.0.0.0:5000 \
        --log-level debug \
        --log-file /var/log/gunicorn/gunicorn.log \
        app:app

运行后，访问 http://localhost:5000 和 http://localhost:5000/api/test ，我们得到 gunicorn.log 日志：

[2022-12-21 17:59:05 +0800] [32174] [DEBUG] Current configuration:
  config: ./gunicorn.conf.py
  wsgi_app: None
  bind: ['0.0.0.0:5000']
  backlog: 2048
  workers: 2
  worker_class: sync
  threads: 1
  worker_connections: 1000
  max_requests: 0
  max_requests_jitter: 0
  timeout: 30
  graceful_timeout: 30
  keepalive: 2
  limit_request_line: 4094
  limit_request_fields: 100
  limit_request_field_size: 8190
  reload: False
  reload_engine: auto
  reload_extra_files: []
  spew: False
  check_config: False
  print_config: False
  preload_app: False
  sendfile: None
  reuse_port: False
  chdir: /home/tattoo/workspace/flask
  daemon: False
  raw_env: []
  pidfile: None
  worker_tmp_dir: None
  user: 1000
  group: 1000
  umask: 0
  initgroups: False
  tmp_upload_dir: None
  secure_scheme_headers: {'X-FORWARDED-PROTOCOL': 'ssl', 'X-FORWARDED-PROTO': 'https', 'X-FORWARDED-SSL': 'on'}
  forwarded_allow_ips: ['127.0.0.1']
  accesslog: None
  disable_redirect_access_to_syslog: False
  access_log_format: %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"
  errorlog: /var/log/gunicorn/gunicorn.log
  loglevel: debug
  capture_output: False
  logger_class: gunicorn.glogging.Logger
  logconfig: None
  logconfig_dict: {}
  syslog_addr: udp://localhost:514
  syslog: False
  syslog_prefix: None
  syslog_facility: user
  enable_stdio_inheritance: False
  statsd_host: None
  dogstatsd_tags:
  statsd_prefix:
  proc_name: None
  default_proc_name: app:app
  pythonpath: None
  paste: None
  on_starting: <function OnStarting.on_starting at 0x7f2ae3bbd4c0>
  on_reload: <function OnReload.on_reload at 0x7f2ae3bbd5e0>
  when_ready: <function WhenReady.when_ready at 0x7f2ae3bbd700>
  pre_fork: <function Prefork.pre_fork at 0x7f2ae3bbd820>
  post_fork: <function Postfork.post_fork at 0x7f2ae3bbd940>
  post_worker_init: <function PostWorkerInit.post_worker_init at 0x7f2ae3bbda60>
  worker_int: <function WorkerInt.worker_int at 0x7f2ae3bbdb80>
  worker_abort: <function WorkerAbort.worker_abort at 0x7f2ae3bbdca0>
  pre_exec: <function PreExec.pre_exec at 0x7f2ae3bbddc0>
  pre_request: <function PreRequest.pre_request at 0x7f2ae3bbdee0>
  post_request: <function PostRequest.post_request at 0x7f2ae3bbdf70>
  child_exit: <function ChildExit.child_exit at 0x7f2ae3bd10d0>
  worker_exit: <function WorkerExit.worker_exit at 0x7f2ae3bd11f0>
  nworkers_changed: <function NumWorkersChanged.nworkers_changed at 0x7f2ae3bd1310>
  on_exit: <function OnExit.on_exit at 0x7f2ae3bd1430>
  proxy_protocol: False
  proxy_allow_ips: ['127.0.0.1']
  keyfile: None
  certfile: None
  ssl_version: 2
  cert_reqs: 0
  ca_certs: None
  suppress_ragged_eofs: True
  do_handshake_on_connect: False
  ciphers: None
  raw_paste_global_conf: []
  strip_header_spaces: False
[2022-12-21 17:59:05 +0800] [32174] [INFO] Starting gunicorn 20.1.0
[2022-12-21 17:59:05 +0800] [32174] [DEBUG] Arbiter booted
[2022-12-21 17:59:05 +0800] [32174] [INFO] Listening at: http://0.0.0.0:5000 (32174)
[2022-12-21 17:59:05 +0800] [32174] [INFO] Using worker: sync
[2022-12-21 17:59:05 +0800] [32176] [INFO] Booting worker with pid: 32176
[2022-12-21 17:59:05 +0800] [32177] [INFO] Booting worker with pid: 32177
[2022-12-21 17:59:05 +0800] [32174] [DEBUG] 2 workers
[2022-12-21 17:59:11 +0800] [32177] [DEBUG] GET /
[2022-12-21 17:59:11 +0800] [32177] [DEBUG] this is a DEBUG message
[2022-12-21 17:59:11 +0800] [32177] [INFO] this is an INFO message
[2022-12-21 17:59:11 +0800] [32177] [WARNING] this is a WARNING message
[2022-12-21 17:59:11 +0800] [32177] [ERROR] this is an ERROR message
[2022-12-21 17:59:11 +0800] [32177] [CRITICAL] this is a CRITICAL message
[2022-12-21 17:59:17 +0800] [32177] [DEBUG] GET /api/test
[2022-12-21 17:59:17 +0800] [32177] [DEBUG] Test DEBUG message
[2022-12-21 17:59:17 +0800] [32177] [INFO] Test INFO message
[2022-12-21 17:59:17 +0800] [32177] [WARNING] Test WARNING message
[2022-12-21 17:59:17 +0800] [32177] [ERROR] Test ERROR message
[2022-12-21 17:59:17 +0800] [32177] [CRITICAL] Test CRITICAL message

你也可以参考 https://docs.python.org/3/library/logging.config.html ，使用 Gunicorn 的 --log-config FILE 选项，用一个日志配置文件来做更精细的日志调整。

对日志文件进行分割

Gunicorn 自身不对日志进行分割，所以我们可以使用 logrotate 工具来实现日志分割的需求。

创建 /etc/logrotate.d/gunicorn 文件：

/var/log/gunicorn/gunicorn.log {
    daily
    dateext
    dateformat -%Y-%m-%d
    dateyesterday
    rotate 90
    missingok
    notifempty
}

daily 每天执行，也可以是 weekly 或 monthly
dateext 使用当期日期作为命名格式
dateformat 日志文件命名格式
rotate 分割次数，如果设置的是daily，就代表保留多少天的记录

如果要立即执行： logrotate -f gunicorn

使用 Docker 部署 Gunicorn + Flask 应用并输出日志

我们在服务器上配置 Python 环境，常常会碰到各种各样的麻烦，而使用现成的 Docker 镜像就很方便，它在各种环境下的行为都能保持一致。

添加 Dockerfile、requirements.txt 和 conf/supervisor_flask.conf 文件：

.
├── api
│   └── test.py
├── app.py
├── conf
│   └── supervisor_flask.conf
├── Dockerfile
└── requirements.txt

Dockerfile

我们使用 alpine 基础镜像以减小镜像体积。使用 supervisord 来后台启动 Gunicorn + Flask。日志输出到 /var/log/flask-app 目录。

FROM python:3-alpine

WORKDIR /home/app

USER root

RUN sed -i 's/dl-cdn.alpinelinux.org/mirrors.aliyun.com/g' /etc/apk/repositories \
    # upgrade pip
    && pip config set global.index-url https://mirrors.aliyun.com/pypi/simple \
    && pip install --upgrade pip \
    # install supervisor gunicorn
    && pip install supervisor gunicorn \
    && mkdir -p /etc/supervisor \
    && /usr/local/bin/echo_supervisord_conf > /etc/supervisor/supervisord.conf \
    && echo "[include]" >> /etc/supervisor/supervisord.conf \
    && echo "files = /etc/supervisor/*.conf" >> /etc/supervisor/supervisord.conf \
    # get curl for healthchecks
    && apk add curl \
    # add log folder
    && mkdir -p /var/log/flask-app

COPY conf/supervisor_flask.conf /etc/supervisor

# copy all the files to the container
COPY . .

# python setup
RUN pip install -r requirements.txt

# define the port number the container should expose
EXPOSE 5000

CMD ["supervisord","-n","-c","/etc/supervisor/supervisord.conf"]

requirements.txt

注意 markupsafe 2.1.0 移除了 soft_unicode，不指定较低版本的话会导致 Flask 报错。

markupsafe==2.0.1
Flask~=1.1.4

conf/supervisor_flask.conf

[supervisord]
nodaemon=true

[program:flask]
command=gunicorn -w 2 -b 0.0.0.0:5000 --log-level debug --log-file /var/log/flask-app/gunicorn.log app:app
directory=/home/app
autostart=true
autorestart=true
redirect_stderr=true
stdout_logfile=/dev/stdout

构建镜像、运行容器

使用下面的命令构建镜像 flasktest：

docker build -t flasktest .

运行，这里我们把日志输出目录映射到了宿主机的 /home/logs 目录：

docker run --name flask \
    -it -d \
    -p 5000:5000 \
    -v /home/logs:/var/log/flask-app \
    flasktest

运行起来后，docker logs -f flask 查看一下容器输出有没有问题，正常的应该是：

$ docker logs -f flasktest
2022-12-22 03:33:32,368 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.
2022-12-22 03:33:32,368 INFO Included extra file "/etc/supervisor/supervisor_flask.conf" during parsing
2022-12-22 03:33:32,368 INFO Included extra file "/etc/supervisor/supervisord.conf" during parsing
2022-12-22 03:33:32,371 INFO RPC interface 'supervisor' initialized
2022-12-22 03:33:32,371 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2022-12-22 03:33:32,372 INFO supervisord started with pid 1
2022-12-22 03:33:33,374 INFO spawned: 'flask' with pid 6
2022-12-22 03:33:34,376 INFO success: flask entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

访问 http://localhost:5000 和 http://localhost:5000/api/test ，我们可以在 /home/logs 目录下找到 gunicorn.log 日志，跟前面的没有什么区别