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

Dear 丶 2023-06-21 03:43 19阅读 0赞

## 问题 ##

在 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` 官方文档][logging_]：

> Warning The [`fileConfig()`][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()`][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()`][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_]
 *  [logging - Can’t get access log to work for gunicorn - Stack Overflow][logging - Can_t get access log to work for gunicorn - Stack Overflow]

## END ##

[logging_]: https://docs.python.org/3/howto/logging.html#configuring-logging
[fileConfig]: https://docs.python.org/3/library/logging.config.html#logging.config.fileConfig
[dictConfig]: https://docs.python.org/3/library/logging.config.html#logging.config.dictConfig
[logging - Can_t get access log to work for gunicorn - Stack Overflow]: https://stackoverflow.com/questions/13472842/cant-get-access-log-to-work-for-gunicorn/20214015#20214015