[小ネタ]uvicornとlogging

[小ネタ]uvicornとlogging

FastAPIと組み合わせてよく使われるuvicornですが、loggingで軽くハマったのでまとめておきます。

uvicornコマンドで起動する場合

uvicornは内部でloggingを使ってログを吐きます。下のシンプルなコードで試してみます。

main.py

from fastapi import FastAPI

app = FastAPI()

@app.get("/hello/{name}")
def hello(name: str) -> dict:
    s = f"Hello, {name}!"
    return {"message": s}

これをuvicornコマンドで起動して、APIを叩いてみます。

shell0

uvicorn main:app --reload
# INFO:     Will watch for changes in these directories: [<省略>]
# INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
# INFO:     Started reloader process [6271] using WatchFiles
# INFO:     Started server process [6273]
# INFO:     Waiting for application startup.
# INFO:     Application startup complete.

shell1

curl localhost:8000/hello/Jack
# {"message":"Hello, Jack!"}

shell0

# INFO:     127.0.0.1:52640 - "GET /hello/Jack HTTP/1.1" 200 OK

適当な名前で別のloggerを作ってもそれはそれで機能します。

main.py

from logging import getLogger, StreamHandler
from fastapi import FastAPI

logger = getLogger(__name__)
logger.addHandler(StreamHandler()) # ただしこれらの設定が必要
logger.setLevel("INFO")            # ただしこれらの設定が必要

app = FastAPI()

@app.get("/hello/{name}")
def hello(name: str) -> dict:
    s = f"Hello, {name}!"
    logger.info(f"Returning {s}")
    return {"message": s}

shell1

curl localhost:8000/hello/Jack
# {"message":"Hello, Jack!"}

shell0

# WARNING:  WatchFiles detected changes in 'main.py'. Reloading...
# INFO:     Shutting down
# INFO:     Waiting for application shutdown.
# INFO:     Application shutdown complete.
# INFO:     Finished server process [8599]
# INFO:     Started server process [8748]
# INFO:     Waiting for application startup.
# INFO:     Application startup complete.
# Returning Hello, Jack!
# INFO:     127.0.0.1:58838 - "GET /hello/Jack HTTP/1.1" 200 OK

loggerの名前としてr"uvicorn(\.[a-zA-Z_][a-zA-Z0-9_]+)+"（例えば下のコードのようにuvicorn.app）を使用するとuvicorn内部のloggerと統合されます。もちろんフォーマットも統一されます。

main.py

from logging import getLogger
from fastapi import FastAPI

logger = getLogger("uvicorn.app")

app = FastAPI()

@app.get("/hello/{name}")
def hello(name: str) -> dict:
    s = f"Hello, {name}!"
    logger.info(f"Returning {s}")
    return {"message": s}

shell1

curl localhost:8000/hello/Jack
# {"message":"Hello, Jack!"}

shell0

# WARNING:  WatchFiles detected changes in 'main.py'. Reloading...
# INFO:     Shutting down
# INFO:     Waiting for application shutdown.
# INFO:     Application shutdown complete.
# INFO:     Finished server process [11681]
# INFO:     Started server process [12045]
# INFO:     Waiting for application startup.
# INFO:     Application startup complete.
# INFO:     Returning Hello, Jack!
# INFO:     127.0.0.1:49762 - "GET /hello/Jack HTTP/1.1" 200 OK

uvicornコマンドの--log-configにログの設定を定義するyamlを指定すると様々にログをカスタマイズすることができます。下記はそういったyamlの例です。

log_config.yaml

version: 1
disable_existing_loggers: false
formatters:
  default:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
    datefmt: '%Y-%m-%d %H:%M:%S'
handlers:
  console:
    class: logging.StreamHandler
    formatter: default
loggers:
  uvicorn:
    handlers:
    - console
    level: INFO

上記を指定してuvicornを起動します。

shell0

uvicorn main:app --reload --log-config log_config.yaml
# 2023-10-17 10:44:04 - uvicorn.error - INFO - Will watch for changes in these directories: [<省略>]
# 2023-10-17 10:44:04 - uvicorn.error - INFO - Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
# 2023-10-17 10:44:04 - uvicorn.error - INFO - Started reloader process [14974] using WatchFiles
# 2023-10-17 10:44:04 - uvicorn.error - INFO - Started server process [14976]
# 2023-10-17 10:44:04 - uvicorn.error - INFO - Waiting for application startup.
# 2023-10-17 10:44:04 - uvicorn.error - INFO - Application startup complete.

shell1

curl localhost:8000/hello/Jack
# {"message":"Hello, Jack!"}

shell1

# 2023-10-17 10:44:47 - uvicorn.app - INFO - Returning Hello, Jack!
# 2023-10-17 10:44:47 - uvicorn.access - INFO - 127.0.0.1:50252 - "GET /hello/Jack HTTP/1.1" 200

このようにログを統合して出力することができます。

Pythonコード内でuvicornを起動する場合

main.py

from logging import getLogger, StreamHandler
from fastapi import FastAPI
import uvicorn

logger = getLogger(__name__)
logger.addHandler(StreamHandler())
logger.setLevel("INFO")

app = FastAPI()

@app.get("/hello/{name}")
def hello(name: str) -> dict:
    s = f"Hello, {name}!"
    logger.info(f"Returning {s}")
    return {"message": s}

if __name__ == "__main__":
    uvicorn.run(app)

上記のようなコードを実行します。

shell0

python main.py
# INFO:     Started server process [27033]
# INFO:     Waiting for application startup.
# INFO:     Application startup complete.
# INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

いつものようにAPIを叩いてみます。

shell1

curl localhost:8000/hello/Jack
# {"message":"Hello, Jack!"}

shell0

# Returning Hello, Jack!
# INFO:     127.0.0.1:51580 - "GET /hello/Jack HTTP/1.1" 200 OK

別名のloggerを作っているので別フォーマットでログが出力されます…とさらっと書きましたが、実はこれ想定外の挙動なのです😅 Pythonコード内でuvicornを起動するプログラムを書いたときに、別名でloggerを作ったところ、uvicornが機嫌を損ねる、あるいはuvicornという名前でloggerを作ってその設定をuvicorn外でいじるとやはりuvicornが機嫌を損ねる、という現象が起きてハマったのですが、再現できませんでした。記事ではログの設定をかなり単純化しているのでそのせいでしょうか？どなたか原因をご存じの方がいらっしゃいましたら教えていただきたいです。この点解明できたら報告しますが、uvicornを使う場合はloggerの名前はuvicornまたはuvicorn.hogeといったものにするのが無難であり良いプラクティスなのはおそらく間違いないと思います。ということでloggerのカスタマイズも含めた模範的なコードは以下のようになります。

main.py

from logging import getLogger
import yaml
from fastapi import FastAPI
import uvicorn

logger = getLogger("uvicorn.app")
app = FastAPI()

@app.get("/hello/{name}")
def hello(name: str) -> dict:
    s = f"Hello, {name}!"
    logger.info(f"Returning {s}")
    return {"message": s}

with open("log_config.yaml", "r") as f:
    config = yaml.safe_load(f)

if __name__ == "__main__":
    uvicorn.run(app, log_config=config)