gunicorn accesslog 为空的一种可能解决办法

问题

在 gunicorn 的配置文件中，有 accesslog 和 errorlog 两项，分别用来记录接口的访问历史和服务启动以及错误消息。

假设有部分配置文件如下：

loglevel = 'info'
accesslog = "log/gunicorn_access.log"
errorlog = "log/gunicorn_error.log"

正常来说服务启动并有相应请求后，应该在 log 目录下应该有非空的 gunicorn_access.log 和 gunicorn_error.log。但是有时我们会发现这两个文件确实存在，只不过 gunicorn_access.log 是空的，而 gunicorn_error.log 正常。

WHY？

当然这里原因众多，我这里只是提出一种可能的原因和解决方案：Python 的 logging 模块导致的。

分析

我们通常会在 app.py 及其他程序中使用 logging 来记录必要信息，在配置 logging 模块时，有可能会使用 logging.config.fileConfig 或者 logging.config.dictConfig，这通常会从一个配置文件中来读取配置。但是其中有个坑，官方也提到了。根据 Python logging 官方文档：

Warning The fileConfig() function takes a default parameter, disable_existing_loggers, which defaults to True for reasons of backward compatibility. This may or may not be what you want, since it will cause any non-root loggers existing before the fileConfig() call to be disabled unless they (or an ancestor) are explicitly named in the configuration. Please refer to the reference documentation for more information, and specify False for this parameter if you wish. The dictionary passed to dictConfig() can also specify a Boolean value with key disable_existing_loggers, which if not specified explicitly in the dictionary also defaults to being interpreted as True. This leads to the logger-disabling behaviour described above, which may not be what you want - in which case, provide the key explicitly with a value of False.

简单来说，就是无论使用 fileConfig() 还是 dictConfig()，都会有个默认值为 True 的参数：disable_existing_loggers，这会导致在调用 fileConfig() 或者 dictConfig() 之前的非 root 的 logger 失效。

OK，那么这和 gunicorn 有什么关系呢？

gunicorn 实际上也是使用的 logging 模块。在真正的启动 flask 服务之前，gunicorn 会先启动，并输出类似如下的信息到 gunicorn_error.log：

[2014-09-10 10:22:28 +0000] [30869] [INFO] Listening at: http://127.0.0.1:8000 (30869)
[2014-09-10 10:22:28 +0000] [30869] [INFO] Using worker: sync
[2014-09-10 10:22:28 +0000] [30874] [INFO] Booting worker with pid: 30874
[2014-09-10 10:22:28 +0000] [30875] [INFO] Booting worker with pid: 30875
[2014-09-10 10:22:28 +0000] [30876] [INFO] Booting worker with pid: 30876
[2014-09-10 10:22:28 +0000] [30877] [INFO] Booting worker with pid: 30877

此时真正的 flask 服务还未启动，也就是 app.py 中的 fileConfig() 或者 dictConfig() 还未执行，此时的非 root logger 还未被禁用，所以 gunicorn_error.log 是正常的。但是随着 flask 服务真正启动之后，gunicorn 的 logger 就被禁用了，后续新请求也就没能够记录，从而导致 gunicorn_access.log 是空的。

解决

那么解决方法也很简单，在 logging 配置文件中将 disable_existing_loggers 设为 False（或者 false）即可。

Reference

• Logging HOWTO — Python 3.8.1rc1 documentation
• logging - Can’t get access log to work for gunicorn - Stack Overflow

END