開発

FastAPIのloggingの設定方法｜uvicornのログ統合・JSON化・リクエストIDをコードで解説

FastAPIのloggingの設定方法｜uvicornのログ統合・JSON化・リクエストIDをコードで解説

FastAPIでlogger.info()を書いたのに何も表示されない。原因はFastAPIではなく、起動役のUvicornが用意するログ設定と、Python標準のloggingの既定値の組み合わせです。この記事では、FastAPI 0.162.7とUvicorn 0.54.0を前提に、まずログが出ない理由をUvicornのソースで確かめ、次にdictConfigでUvicornとアプリのログを1つの設定にまとめます。そのうえで、JSON形式の構造化ログ、リクエストIDによる相関、外部入力に混ざった改行でログを偽装される問題の防ぎ方まで、動かせるコードで順に組み立てます。

まとめ：FastAPIのログ設定で最初に決めておく4つの結論

アプリのログが出ないのは、Uvicornの既定設定がuvicorn系のロガーにしかハンドラーを付けないためです。--log-level debugを付けてもアプリのロガーには効きません。ルートロガーにハンドラーを付ける設定を、自分で1つ用意します。

設定はdictConfigの辞書1つにまとめ、"disable_existing_loggers": Falseを必ず書きます。省くと既定値がTrueになり、Uvicornの起動ログ、アクセスログ、例外のトレースバックまで黙って消えます。

本番では1行1件のJSONで標準出力に書き、全行にリクエストIDを載せます。JSONにすると、利用者が送った改行もエスケープされ、偽のログ行を差し込まれません。リクエストIDはContextVarとlogging.Filterで付けますが、ミドルウェアで値を戻す処理を入れると、500エラーの例外ログだけIDが消えます。

FastAPIでlogger.infoが出ない原因とuvicorn 0.54の既定設定

設定を書く前に、何も設定しない状態でどのロガーがどこへ書いているかを把握します。ここを飛ばすと、後の設定でどのロガーを上書きしているのかが分からなくなります。

uvicorn・uvicorn.error・uvicorn.accessの出力先の違い

Uvicorn 0.54.0のconfig.pyにある既定の設定LOGGING_CONFIGは、次の3つのロガーだけを定義しています。

ロガー名 出力先 propagate 出す内容
uvicorn 標準エラー False 親。下のuvicorn.errorを受ける
uvicorn.error （親へ渡す） 指定なし 起動・停止・例外
uvicorn.access 標準出力 False 1リクエスト1行のアクセスログ

uvicorn.errorという名前ですが、公式のログの説明どおり、エラー専用ではなく「Started server process」のような起動メッセージもここから出ます。ログ基盤でロガー名を条件にエラーを数える方法では、起動のたびに誤検知する結果になるため注意が必要です。数えるならレベル（ERROR以上）で判定します。

アプリのlogger.infoが出ずWARNINGだけ素の文字列で出る理由

アプリ側でlogging.getLogger(__name__)を作ると、そのロガーはルートロガーへ記録を渡します。ところが上の設定はルートロガーにハンドラーを付けていません。ハンドラーが1つも見つからないとき、PythonはLogging HOWTOが説明する最後の手段のハンドラー（lastResort）を使います。このハンドラーのレベルはWARNINGで、書式を付けずにメッセージだけを標準エラーへ書きます。

Starlette 1.10.0（FastAPIの土台）とUvicorn 0.54.0で実際に起動して確かめると、logger.info("items called")は出力されず、logger.warning("q=%s", q)はq=abcとだけ表示されました。レベル名も時刻もロガー名も付きません。「INFOが出ない」「WARNINGは出るのに形式がおかしい」という2つの症状は、同じ原因です。

fastapi runがTTYの有無でログ設定を切り替える仕様と–log-level

fastapi runとfastapi devは内部でuvicorn.run()を呼びます。fastapi-cli 0.0.34のソースでは、標準出力が端末（TTY）のときだけ独自の色付きログ設定を渡し、そうでないときはUvicornの既定に任せます。手元の端末とコンテナで見た目が違うのはこのためで、コンテナで表示されるのはUvicornの既定の形式です。fastapi runにはログ設定ファイルを渡すオプションがありません。

Uvicornの設定一覧にある--log-levelも、ソースを読むとuvicorn.error・uvicorn.access・uvicorn.asgiのレベルを変えるだけです。アプリのロガーは対象外なので、アプリのログを出すには次の章の設定が要ります。起動方法そのものはFastAPIの最短の起動手順を参照してください。

dictConfigでuvicornとアプリのログを1つの設定にまとめる手順

logging.basicConfig()を1行足せばアプリのログは出ます。ただしUvicornのログとは別の形式・別の出力先のまま残るため、本番ではdictConfigの辞書1つでUvicornのロガーごと定義し直します。

disable_existing_loggers省略時のuvicornログ・例外の消失

logging.configの説明によると、dictConfigのdisable_existing_loggersは省略するとTrueです。アプリのモジュールで読み込んだ時点で、Uvicornのロガーはすでに作られているため、まとめて無効になります。

ルートロガーだけを定義し、この項目を書かない辞書をアプリで読み込んで実測したところ、Uvicornの起動ログ、アクセスログ、Exception in ASGI applicationで始まる例外のトレースバックが1行も出なくなりました。アプリのログだけは出るため、障害が起きるまで気付きにくい失敗です。Alembicのenv.pyが生成するfileConfig()も同じ既定値なので、マイグレーションをアプリから呼ぶ構成では同じことが起きます。

log_setup.pyにuvicornとルートロガーの設定を同じ辞書で書く

設定は1ファイルにまとめます。JSONの整形とリクエストIDの付与もこのファイルに置き、次の章で中身を説明します。

# log_setup.py
import json
import logging
from contextvars import ContextVar

# リクエストごとのIDを保持する（リクエスト外では「-」）
request_id_var: ContextVar[str] = ContextVar("request_id", default="-")


class RequestIdFilter(logging.Filter):
    """すべてのログレコードに request_id 属性を足す"""

    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id_var.get()
        return True


class JsonFormatter(logging.Formatter):
    """1レコードを1行のJSONにする"""

    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "time": self.formatTime(record, "%Y-%m-%dT%H:%M:%S%z"),
            "level": record.levelname,
            "logger": record.name,
            "request_id": getattr(record, "request_id", "-"),
        }
        # uvicorn.access は args に (client, method, path, http_version, status) を持つ
        if record.name == "uvicorn.access" and isinstance(record.args, tuple) and len(record.args) == 5:
            client, method, path, http_version, status = record.args
            payload.update(client=client, method=method, path=path, status=status)
        payload["message"] = record.getMessage()
        if record.exc_info:
            payload["exc_info"] = self.formatException(record.exc_info)
        return json.dumps(payload, ensure_ascii=False)


LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,  # 省くと uvicorn のロガーが無効になる
    "filters": {"request_id": {"()": "log_setup.RequestIdFilter"}},
    "formatters": {"json": {"()": "log_setup.JsonFormatter"}},
    "handlers": {
        "stdout": {
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",
            "formatter": "json",
            "filters": ["request_id"],
        },
    },
    "loggers": {
        "uvicorn": {"handlers": ["stdout"], "level": "INFO", "propagate": False},
        "uvicorn.error": {"level": "INFO"},
        "uvicorn.access": {"handlers": ["stdout"], "level": "INFO", "propagate": False},
    },
    "root": {"handlers": ["stdout"], "level": "INFO"},
}

フィルターはロガーではなくハンドラーに付けます。ロガーに付けたフィルターは、子のロガーから伝わってきた記録には掛からないためです。ハンドラーに付ければ、アプリのロガーもUvicornのロガーも同じrequest_idを持ちます。

–log-configで渡す方法とアプリのモジュールで読み込む方法

読み込み方は2通りあり、どちらか一方だけを使います。1つ目はUvicornの--log-configにJSONファイルを渡す方法です。拡張子が.jsonならdictConfigで読まれます。

# log_setup.LOGGING を JSON ファイルに書き出し、uvicorn に渡す
python -c "import json, log_setup; print(json.dumps(log_setup.LOGGING, indent=2))" > logging.json
uvicorn main:app --host 0.0.0.0 --port 8000 --log-config logging.json

2つ目はアプリのモジュールの先頭でlogging.config.dictConfig(LOGGING)を呼ぶ方法です。Uvicornは自分のログ設定を済ませてからアプリを読み込むので、後から読んだアプリ側の設定が上書きします。fastapi runのようにログ設定ファイルを渡せない起動方法でも効くため、迷ったらこちらを選びます。実測では、どちらの方法でも起動ログからアクセスログまでがすべて同じJSON形式になりました。

JSON構造化ログとリクエストIDで1リクエスト分のログを相関させる実装

ログを1行1件のJSONにすると、ログ基盤でrequest_idやstatusを条件に絞り込めます。JSONで書く理由そのものは構造化ログの仕組みとslog・structlogの実装で扱っているので、ここではFastAPIとUvicornに固有の部分に絞ります。

JsonFormatterでのargs分解とmethod・path・statusの抽出

Uvicornのアクセスログは、メッセージを組み立て済みの文字列で渡しません。logging.pyのAccessFormatterはrecord.argsを、接続元・メソッド・パス・HTTPの版・ステータスの5要素として分解しています。上のJsonFormatterも同じ順で取り出し、項目に分けています。出力は次のようになります（実測の1行を折り返して表示）。

{"time": "2026-11-14T06:11:11+0900", "level": "INFO", "logger": "app.items",
 "request_id": "req-123", "message": "items called"}
{"time": "2026-11-14T06:11:11+0900", "level": "INFO", "logger": "uvicorn.access",
 "request_id": "req-123", "client": "127.0.0.1:52802", "method": "GET",
 "path": "/items?q=abc", "status": 200,
 "message": "127.0.0.1:52802 - \"GET /items?q=abc HTTP/1.1\" 200"}

例外のトレースバックもexc_infoという1項目の文字列に収まります。複数行のトレースバックを行単位で取り込むログ基盤では、1件の例外が数十件のログに割れてしまうため、この1行化だけでも障害調査の手間が変わります。

ContextVarとlogging.FilterでリクエストIDを全レコードへ付与する

リクエストIDは、リクエストの入口でcontextvarsの変数に入れ、RequestIdFilterが記録のたびに読み出します。入口には純ASGIミドルウェアを使います。

# main.py
import logging
import logging.config
import re
import uuid

from fastapi import FastAPI
from starlette.datastructures import Headers, MutableHeaders

from log_setup import LOGGING, request_id_var

logging.config.dictConfig(LOGGING)  # uvicorn の設定より後に読まれ、上書きする
logger = logging.getLogger(__name__)

# 外部から来る X-Request-ID は英数字とハイフンの64文字以内だけ受け入れる
_VALID_ID = re.compile(r"[A-Za-z0-9-]{1,64}")


class RequestIdMiddleware:
    def __init__(self, app):
        self.app = app

    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            await self.app(scope, receive, send)
            return
        incoming = Headers(scope=scope).get("x-request-id", "")
        request_id = incoming if _VALID_ID.fullmatch(incoming) else uuid.uuid4().hex
        request_id_var.set(request_id)  # reset しない理由は次の項で説明

        async def send_with_id(message):
            if message["type"] == "http.response.start":
                MutableHeaders(scope=message)["x-request-id"] = request_id
            await send(message)

        await self.app(scope, receive, send_with_id)


app = FastAPI()
app.add_middleware(RequestIdMiddleware)


@app.get("/items")
async def read_items(q: str = ""):
    logger.info("items called")
    logger.warning("q=%s", q)
    return {"q": q}
# 起動（--reset-contextvars の意味は次の項）
uvicorn main:app --port 8000 --reset-contextvars

# 別の端末から、IDを付けた要求を送る
curl -i -H "X-Request-ID: req-123" "http://127.0.0.1:8000/items?q=abc"

Uvicornはアクセスログを、アプリが応答の開始をsendした時点で書きます（h11_impl.py）。その呼び出しはミドルウェアの中で起きるため、アクセスログにも同じIDが載ります。BaseHTTPMiddlewareとの違いや、IDを応答ヘッダーに返す部分の詳細はFastAPIのミドルウェアの使い方で解説しています。

500例外のID消失の原因と–reset-contextvarsによる対策

ContextVarは使い終わったらreset()で戻す、という書き方がよく紹介されます。ところがミドルウェアのfinallyで戻すと、500エラーの記録からIDが消えます。未処理の例外はミドルウェアを抜けたあとで、外側のエラー処理が500を返し、Uvicornが例外ログを書くからです。実測では、reset()ありの構成で、500のアクセスログと例外ログのrequest_idがどちらも-になりました。

Uvicornは1リクエストごとに別のタスクを作り、変数の値はそのタスクの中に閉じます。そのため戻さなくても次のリクエストには持ち越しません。さらに–reset-contextvarsを付けると、リクエストごとに空のコンテキストから始まります。リリースノートでは0.45.0（2026年4月21日）で追加された設定で、asyncioのコンテキスト漏れへの回避策と説明されています。reset()なし・--reset-contextvarsありの構成では、500のアクセスログと例外ログの両方にreq-500が残りました。ただし、この設定はlifespanや計測ツールが入れた値もリクエスト側から見えなくします。lifespanでContextVarを使っている場合は、付ける前に影響を確かめてください。

外部入力をログに出すときのCR/LF除去とログ偽装を防ぐテスト

クエリ・ヘッダー・本文の値をそのままログに書くと、利用者が送った改行で偽のログ行を作られます。CWE-117として分類されている問題で、OWASPのLogging Cheat SheetもCR・LFの除去を求めています。

クエリの%0D%0Aで偽のログ行が作られるテキスト形式の実測

basicConfig()のテキスト形式のまま、/items?q=x%0D%0AINFO%20fake%20admin%20loginを送って確かめました。FastAPIやStarletteはクエリの%0D%0Aを改行に戻して渡すので、logger.warning("q=%s", q)の出力は次のように2行に割れます。

WARNING app.items q=x

INFO fake admin login

2行目は、本物のINFOログと見分けがつきません。一方、Uvicornのアクセスログ側は、パスをurllib.parse.quoteで、クエリを受け取ったままの%0D%0Aで書くため、1行に収まっていました。危ないのは、アプリが値を取り出して自分で書くログの方です。

JSON化とX-Request-IDの形式検証で防ぐ範囲とテストでの確認

JSONで書けば、json.dumpsが改行を\r\nという文字列にエスケープするので、偽の行は生まれません。同じ要求をJsonFormatterで出すと、"message": "q=x\r\nINFO fake admin login"の1行になりました。ヘッダーから受け取るリクエストIDは、ログだけでなく応答ヘッダーにも返す値なので、エスケープに頼らず正規表現で形式を検証し、合わなければ捨てて新しく発行します。テキスト形式を残す場合は、ログに渡す前にvalue.replace("\r", "\\r").replace("\n", "\\n")のように置き換える関数を通します。

# test_log_setup.py（pytest で実行）
import json
import logging

from log_setup import JsonFormatter, RequestIdFilter, request_id_var


def make_record(msg, *args, exc_info=None):
    return logging.LogRecord("app.items", logging.WARNING, __file__, 1, msg, args, exc_info)


def test_crlf_in_user_input_stays_in_one_line():
    record = make_record("q=%s", "x\r\nINFO fake admin login")
    RequestIdFilter().filter(record)
    line = JsonFormatter().format(record)
    assert "\n" not in line and "\r" not in line
    assert json.loads(line)["message"] == "q=x\r\nINFO fake admin login"


def test_request_id_is_attached():
    token = request_id_var.set("req-123")
    try:
        record = make_record("hello")
        RequestIdFilter().filter(record)
        assert json.loads(JsonFormatter().format(record))["request_id"] == "req-123"
    finally:
        request_id_var.reset(token)


def test_traceback_is_one_line():
    try:
        raise RuntimeError("boom")
    except RuntimeError as e:
        record = make_record("failed", exc_info=(type(e), e, e.__traceback__))
    line = JsonFormatter().format(record)
    assert "\n" not in line
    assert "RuntimeError: boom" in json.loads(line)["exc_info"]

3本とも、整形した1行に改行が残らないことを確かめるテストです。JsonFormatterをlogging.Formatter("%(message)s")に差し替えると1本目が落ちるので、整形を変えたときの回帰を拾えます。テストの中でreset()を使うのは、テスト同士で値を持ち越さないためで、ミドルウェアの書き方とは事情が違います。

本番運用でログの出力先と量を決めるときの判断基準とやめる構成

設定が動いたら、どこへ書き、どこまで作り込むかを決めます。ここは迷いやすい2点に絞って結論を書きます。

複数ワーカーでFileHandlerに書かず標準出力へ集める理由

--workers 4のように複数プロセスで動かすときは、各プロセスから同じファイルへ書く構成をやめます。Logging Cookbookは、複数プロセスから1つのファイルへ書くことを、Pythonでは書き込みを順番に並べる標準の手段が無いためサポートしないと明記しています。RotatingFileHandlerのローテーションも、各プロセスがそれぞれ独立して動かす仕組みです。

標準出力に書き、コンテナ実行基盤やsystemdの仕組みに集めてもらうのが素直です。ワーカー数や起動方法の選び方はUvicornの起動と本番設定にまとめています。

標準ライブラリで足りる場面とstructlogやOpenTelemetryへ進む条件

この記事のlog_setup.pyは標準ライブラリだけで書いています。サービスが1つで、ログ基盤でrequest_idを条件に検索できれば十分という段階なら、追加のライブラリは入れません。依存が増えるほど、Uvicornの版上げのたびに確認する範囲も広がります。

ログに載せる項目が処理ごとに増え、extra=の指定が散らばってきたらstructlog（2026年11月時点で26.1系）へ移ります。複数のサービスをまたいで1つの要求を追う必要が出たら、自前のリクエストIDではなくトレースIDに揃える段階で、OpenTelemetryのログ実装と送信経路の選び分けが次の参照先です。どのレベルを本番に残すかはログレベルの使い分けと本番で残す量の設計で扱っています。ログ基盤の選定や、CI/CDと合わせた運用の仕組みづくりから相談したい場合は、DevOps・CI/CD導入支援で受け付けています。

よくある質問

FastAPIのログ設定について、実装中によく出る質問に2026年11月時点の版で答えます。

logging.basicConfigだけで済ませてはいけませんか？

開発中に手元で見るだけなら、basicConfig(level=logging.INFO)で構いません。この設定を加えたあとのアプリのログの出力先は、標準エラーです。ただしUvicornのログは別の形式のまま残り、アクセスログは標準出力、アプリのログは標準エラーと出力先も分かれます。本番でログ基盤に取り込むなら、この記事のdictConfigで形式と出力先を揃えます。

uvicorn.runで起動する場合はどこで設定を渡しますか？

uvicorn.run("main:app", log_config=LOGGING)のように、log_configに辞書をそのまま渡せます。ファイルのパスを渡すことも可能で、拡張子が.jsonか.yamlの場合に読み込みを担うのはdictConfigです。YAMLを使うにはPyYAMLが要り、uvicorn[standard]で入ります。アプリ側でもdictConfigを呼ぶと二重になるので、どちらか一方に決めます。

アクセスログを止めて自前のミドルウェアで出してもよいですか？

よいです。--no-access-logで止められ、uvicorn.errorのログには影響しません。処理時間やユーザーIDなど、アクセスログに無い項目を足したいときの選択肢です。ただし、未処理の例外が起きた要求ではcall_nextが応答を返さずに例外を投げるため、自前のミドルウェアで捕まえていないと記録から漏れます。例外ログ（uvicorn.error）は止めずに残します。

log_setup.pyはプロジェクトのどこに置けばよいですか？

アプリの起点（main.py）から最初に読み込める位置に置き、ルーターやサービス層からはlogging.getLogger(__name__)でロガーを取るだけにします。設定を読み込む場所を1か所にすると、二重の設定を防げます。ディレクトリ全体の分け方はFastAPIのベストプラクティスとディレクトリ構成を参考にしてください。

起動時や終了時の処理のログにもリクエストIDは付きますか？

付きません。リクエストの外で書いたログは、ContextVarの既定値である-になります。起動時のDB接続やモデルの読み込みのログを区別したいなら、lifespanで書く起動・終了の処理の中で専用のロガー名を使い、loggerの項目で絞り込めるようにします。

関連記事

お気に入りに入れた記事の一覧

一創の公式 SNS

X では毎朝の新着記事と IT ニュースの速報を、YouTube・TikTok・Instagram・LinkedIn・Facebook では記事の解説動画を配信しています。

この記事は以下の記事からリンクされています

この記事に関連するサービス

資料請求

今日のトレンド記事 直近 24 時間で、いつもより多く読まれている記事

  1. 2026.11.13　テックブログ 宝くじ公式サイト不正アクセス：4,436名の対象確認とパスワード再設定、変更された仕組み
  2. 2026.11.13　テックブログ KARTEの不正アクセス：全機能停止で利用企業がタグ・配信・データ連携を確かめる手順
  3. 2026.10.21　テックブログ マネックス証券の不正アクセス：メールアドレス最大約113万件と本人確認画像1,592件の漏えいのおそれ、口座開設停止とPHP脆弱性との関係
  4. 2026.11.14　テックブログ ヤマダデンキの不正アクセス：リフォーム管理システム最大350万件と、住所・見積を持つ営業記録の守り方
  5. 2026.11.11　テックブログ Microsoft 2026年11月の月例更新：Outlookの悪用済みCVE-2026-124194と修正版の確認方法

RELATED POSTS 関連記事

一覧へ戻る

目次