gunicorn accesslog 為空的一種可能解決辦法

• 2019 年 12 月 20 日
• 筆記

問題

在 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