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

gunicornのエラーログのフォーマットを変更しようと思ったのですが、エラーログのフォーマットに関する設定値が無い（ [ドキュメント](https://docs.gunicorn.org/en/stable/settings.html#logging) ）ようなので、自分で変更してみようと思います。  
アクセスログのフォーマット設定（ `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のデフォルトの出力を書いておきます。タイムスタンプが秒単位で表示されるなど、少し気になるところがあります。

```log
[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 で出力する](https://qiita.com/hoto17296/items/fa840823245fa4e7517d)  
[標準ライブラリの範囲で構造化ログで出力するようにしてみる](https://pod.hatenablog.com/entry/2017/05/20/232522)


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

`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
```