gunicornのエラーログのフォーマットを変更する

gunicornのエラーログのフォーマットを変更しようと思ったのですが、エラーログのフォーマットに関する設定値が無い（ ドキュメント ）ようなので、自分で変更してみようと思います。
アクセスログのフォーマット設定（ access_log_format ）も何故か機能しないのですが、同じ方法で変更できました。ただ、 %(h)s などカスタムログ書式は使えない？ようです。
なお、ここではワーカープロセスのログのみ変更します。マスタープロセスのログの変更も少し試したのですが、あまり良い方法が思いつかなかったので、最後のおまけに書く程度にとどめておきます。

以下のバージョンで動作確認しています。

$ python -V
Python 3.9.16
$ pip freeze  # 一部のみ抜粋
gunicorn==20.1.0
uvicorn==0.21.0
fastapi==0.94.1

デフォルトのログフォーマット

gunicornのデフォルトの出力を書いておきます。タイムスタンプが秒単位で表示されるなど、少し気になるところがあります。

[2023-03-14 20:33:12 +0900] [48040] [INFO] Starting gunicorn 20.1.0
[2023-03-14 20:33:12 +0900] [48040] [INFO] Listening at: http://127.0.0.1:8000 (48040)
[2023-03-14 20:33:12 +0900] [48040] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2023-03-14 20:33:12 +0900] [48098] [INFO] Booting worker with pid: 48098
[2023-03-14 20:33:12 +0900] [48098] [INFO] Started server process [48098]
[2023-03-14 20:33:12 +0900] [48098] [INFO] Waiting for application startup.
[2023-03-14 20:33:12 +0900] [48098] [INFO] Application startup complete.

ワーカープロセスのフォーマット変更

構成

フォーマットの修正のみなので、簡単な構成にしています。ログ変更にあたって特別な制限は無いと思います。

$ tree
.
├── app_logging.py          # ワーカー起動時の処理。今回はログ設定のみ
├── gunicorn_settings.py    # gunicornのconfigファイル
├── log
│   └── app.log             # エラーログ出力先
└── main.py

各ファイルについて

ポイントは以下のとおりです。

• app_logging.py
  • logger = logging.getLogger("gunicorn.error") でgunicornのエラーログを取得する
    • "gunicorn.error" としない場合、gunicorn側のログ（ Internal Server Error が発生するようなケースなど）が出力できなくなります。
    • "gunicorn.access" とすると、同様の方法でアクセスログのフォーマット変更ができます。
  • フォーマット含め、基本的にこの中でログ設定をする
• gunicorn_settings.py
  • errorlog パラメータを設定しない（デフォルトのまま）
    • app_logging.py の中でファイルハンドラを追加しているため、設定するとログが重複して出力されます。
    • loglevel は指定しても大丈夫です。

また、注意点として、 app_logging.py の logger.setLevel(logging.INFO) で指定するログレベルは logger.info() などで出力するログのレベルです。
gunicorn側で loglevel = 'info' としていても、app_logging.py 側で logging.ERROR などに設定している場合は logger.info() が出力されなくなります。（このあたりがやや複雑ですが…）

main.py はログ出力しているだけなので、特に注意事項はないです。（強いて言えば app_logging.py を先に処理させる程度）

app_logging.py

import logging

logger = logging.getLogger("gunicorn.error")
logger.setLevel(logging.INFO)

fh = logging.FileHandler("log/app.log")
logger.addHandler(fh)

fmt = logging.Formatter("%(asctime)s - %(levelname)s -- %(message)s")
fh.setFormatter(fmt)

gunicorn_settings.py

wsgi_app = "main:app"
bind = "127.0.0.1:8000"
worker_class = "uvicorn.workers.UvicornWorker"

main.py

from fastapi import FastAPI

from app_logging import logger


app = FastAPI()


@app.get("/")
def root():
    logger.info("log message")

    return {"message": "Hello, world!"}

あとは以下でアプリを起動して、curlなどでリクエストします。

$ gunicorn --config gunicorn_settings.py

ログ出力結果

指定した通りのフォーマットになりました。
loggingのフォーマットでできることは全てできるはずなので、プロセスIDなども出力できます。

log/app.log

2023-03-14 20:33:12,909 - INFO -- Started server process [48098]
2023-03-14 20:33:12,909 - INFO -- Waiting for application startup.
2023-03-14 20:33:12,909 - INFO -- Application startup complete.
2023-03-14 20:33:26,962 - INFO -- log message
2023-03-14 20:33:32,781 - INFO -- Shutting down
2023-03-14 20:33:32,881 - INFO -- Waiting for application shutdown.
2023-03-14 20:33:32,882 - INFO -- Application shutdown complete.
2023-03-14 20:33:32,882 - INFO -- Finished server process [48098]
2023-03-14 20:33:32,883 - INFO -- Worker exiting (pid: 48098)

また、gunicorn側のログも出力できるため、例えば Internal Server Error が発生した場合でもTracebackが出力されます。

2023-03-14 20:35:56,905 - ERROR -- Exception in ASGI application
Traceback (most recent call last):
（以下大量のTraceback）

ただし、Traceback自体は通常のフォーマットで出力されるため、そこまで含めて制御したい場合はもう少し手間がかかります。
ログを構造化したり、JSONにして出力する方法もあるので、その中でリストに整形すると見やすいかもしれません。
Python のログを JSON で出力する
標準ライブラリの範囲で構造化ログで出力するようにしてみる

（おまけ）マスタープロセスのフォーマット変更

app_logging.py はマスタープロセスが起動した後、ワーカープロセスを準備するときに実行されるため、上記の方法ではマスタープロセスのログフォーマット変更はできません。
また、 gunicorn_settings.py で errorlog を省略しているため、全てデフォルトの出力先（19.2以降は標準エラー）に出力されます。

少し試して以下の方法で変更できることがわかったのですが、configに影響する可能性がある上、邪道な気がするので軽く紹介する程度にします。
構成と main.py 、実行方法は最初と同じです。

gunicorn_settings.py

import logging  # 追加

wsgi_app = "main:app"
bind = "127.0.0.1:8000"
worker_class = "uvicorn.workers.UvicornWorker"

# --- ここから追加 ---
# ここでログ設定してしまう
logger = logging.getLogger("gunicorn.error")
logger.setLevel(logging.INFO)
fh = logging.FileHandler("log/app.log")
fmt = logging.Formatter("[MASTER] %(asctime)s - %(levelname)s -- %(message)s")
fh.setFormatter(fmt)
logger.addHandler(fh)
# --- ここまで追加 ---

app_logging.py

import logging

logger = logging.getLogger("gunicorn.error")
logger.setLevel(logging.INFO)

# --- ここから追加 ---
# マスタープロセスのファイルハンドラを削除（残しておくとログが重複する）
fh_list = logger.handlers.copy()
for h in fh_list:
    if type(h) is logging.FileHandler:
        logger.removeHandler(h)
# --- ここまで追加 ---

# ワーカープロセスのファイルハンドラを作成
fh = logging.FileHandler("log/app.log")
logger.addHandler(fh)

fmt = logging.Formatter("[WORKER] %(asctime)s - %(levelname)s -- %(message)s")  # 判別のため[WORKER]の文字列を追加
fh.setFormatter(fmt)

ログ出力結果

log/app.log

[MASTER] 2023-03-14 20:34:43,010 - INFO -- Starting gunicorn 20.1.0
[MASTER] 2023-03-14 20:34:43,012 - INFO -- Listening at: http://127.0.0.1:8000 (49147)
[MASTER] 2023-03-14 20:34:43,012 - INFO -- Using worker: uvicorn.workers.UvicornWorker
[MASTER] 2023-03-14 20:34:43,014 - INFO -- Booting worker with pid: 49205
[WORKER] 2023-03-14 20:34:43,204 - INFO -- Started server process [49205]
[WORKER] 2023-03-14 20:34:43,204 - INFO -- Waiting for application startup.
[WORKER] 2023-03-14 20:34:43,205 - INFO -- Application startup complete.
[WORKER] 2023-03-14 20:34:46,595 - INFO -- log message
[MASTER] 2023-03-14 20:34:50,091 - INFO -- Handling signal: int
[WORKER] 2023-03-14 20:34:50,129 - INFO -- Shutting down
[WORKER] 2023-03-14 20:34:50,230 - INFO -- Waiting for application shutdown.
[WORKER] 2023-03-14 20:34:50,230 - INFO -- Application shutdown complete.
[WORKER] 2023-03-14 20:34:50,230 - INFO -- Finished server process [49205]
[WORKER] 2023-03-14 20:34:50,231 - INFO -- Worker exiting (pid: 49205)
[MASTER] 2023-03-14 20:34:50,393 - INFO -- Shutting down: Master