FastAPIでマルチプロセスのままlog設定

はじめに

FastAPIでのLogの取り扱いについてです。
FastAPIのログでPython標準ライブラリのPython loggingを何も気にせずに使用するとバグが発生してしまうので、理由や解決策について記述していきます。

問題

Python loggingは単一プロセスの複数スレッドからのログ書込みはサポートされていますが、マルチプロセスからのログ書込みはサポートされていません。普通にファイルの中でasync/awaitを使っているだけでは単一プロセスの複数スレッドなのでスレッドセーフな書込みが可能ですが、マルチプロセスのサーバを起動する場合はそうはいきません。
Fastapiサーバで使用されるuvicornはデフォルトでマルチプロセスとなっているので、単一プロセスと同じようにloggingを使ってしまうとバグが発生します。自分も間違えてやってしまったことがありますが、ファイルがバグって壊れてしまい大変でした。uvircorn起動時のコマンドでワーカー数を1と指定 (--workers 1 を追記) すれば単一プロセスとはなりますが、それではFastAPIのせっかくの高速性が失われてしまいますので、マルチプロセスのまま綺麗にlog設定をしたいものですね。

解決

マルチプロセスで単一ログファイルへ記録する場合、Python Logging公式では以下のような方法が紹介されています。

• multiprocessing モジュール の Lock クラスでアクセスを直列化
• Queue と QueueHandler を使って、1つのプロセスに全ての logging イベントを送る

どちらも結局は複数プロセスからの受付を単一のプロセスに集約し、その単一プロセスの中でLoggerを定義してあげるということで、根本的には似ていそうですが、ちょっと面倒そうです。

他に良い方法がないかと思っていたら、uvicornの機能として、yaml記述したlog設定ファイルをuvicornの起動時にコマンドオプション( --log-config ***.yaml )で指定すれば簡単にできたので、今回はそれを紹介します。
せっかくなので、uvicornが標準でサポートしているログ(uvicorn.access, uvicorn.error)のフォーマットを変えたり、syslog以外の出力設定として1日毎にログファイルを作成して保存するようにしたり、それに加えて自作のロガーも追加したりしていきます。

log_conf.yamlの設定

FastAPIのルートディレクトリに以下のようにlog_conf.yamlを作成します。

log_conf.yaml

version: 1
disable_existing_loggers: False
formatters:
  # uvicorn用のフォーマット
  f_uvicorn:
    format: '[UVICORN] %(asctime)s %(levelname)s %(name)s %(message)s'
  # カスタムログ用のフォーマット    
  f_custom:
    format: "[CUSTOM] %(asctime)s %(levelname)s %(name)s (%(funcName)s[%(lineno)s]) %(message)s"
handlers:
  # uvicornで備わっているlogを標準出力するハンドラ
  h_console_uvicorn:
    class: logging.StreamHandler
    formatter: f_uvicorn
    stream: ext://sys.stdout
  # 自分で設定したカスタムログを標準出力するハンドラ
  h_console_custom:
    class: logging.StreamHandler
    formatter: f_custom
    stream: ext://sys.stdout
  # uvicornで備わっているlogをファイル出力(毎日ファイルを更新しながら365日分出力)するハンドラ
  h_file_uvicorn:
    class : logging.handlers.TimedRotatingFileHandler
    formatter: f_custom
    filename: logs/uvicorn/uvicorn.log
    when: midnight
    backupCount: 365
    encoding: utf-8    
  # 自分で設定したカスタムログをファイル出力(毎日ファイルを更新しながら365日分出力)するハンドラ
  h_file_custom:
    class : logging.handlers.TimedRotatingFileHandler
    formatter: f_custom
    filename: logs/costom/custom.log
    when: midnight
    backupCount: 365
    encoding: utf-8
loggers:
  # uvicornで備わっているログはpropagateをtrueにしてroot設定を引継ぐ
  uvicorn.error:
    propagate: true
  uvicorn.access:
    propagate: true
  # カスタムログでは、標準出力とlogs/custom/custom.logへ出力
  custom:
    level: INFO
    handlers:
      - h_console_custom
      - h_file_custom
    propagate: false
  # uvicornでは標準出力とlogs/uvicorn/uvicorn.logへ出力 (propagateされて来る)
  root:
    level: INFO
    handlers: 
      - h_console_uvicorn
      - h_file_uvicorn    

ここでのuvicorn.errorとuvicorn.accessは既にuvicornで初めから備わっているロガー名になります。DockerでFastAPIを構築している人は、logsコマンドでコンテナログが見れてFastAPIの場合はAPIへの受付記録や内部エラー記録が見れますが、その出力をしているのがこのuvicorn.errorとuvicorn.accessとなります。コンテナ内の標準出力(stdout)にアウトプットされ、その内容がdockerを通してlogsコマンドで見れる仕組みです。

上述のlog_confではuvicornのデフォルトログ設定のフォーマッターを変え、標準出力と同時にファイルへも出力されるようにしていますので、ファイルでも確認できつつ、Docker logsコマンドでの確認もできます。まとめると、以下のような出力設定になっています。

• uvicorn.error -> syslogとlogs/uvicorn/uvircorn.log
• uvicorn.access -> syslogとlogs/uvicorn/uvircorn.log
• 自作ロガー -> syslogとlogs/custom/custom.log

このように設定することで、logs/uvicornにはuvicorn.log.YYYY-MM-DDと、logs/customにはcustom.log.YYYY-MM-DDと毎日ログが出力保存されていきます。ここではuvicornのエラーログとアクセスログを同じログファイルに記録していますが、別々のファイルにするのも分かりやすくていいでしょう。その場合は、uvicornのエラー用ハンドラとアクセス用ハンドラを追加して、propagateを止めて、accessとerrorそれぞれのロガーにそれぞれのハンドラをアタッチしてあげます。

ちなみに、ログフォルダ自体は初めから存在しないといけないです。git管理をする場合、logsフォルダを空にしてしまうと他の人がcloneしたときにlogs/uvicornやlogs/customディレクトリが存在せず、ログ出力エラーになってしまいますので、それぞれに空の.gitkeepファイルを作成してあげましょう。

自作ロガーをファイルで扱う

カスタムログをファイル内で使用する場合は、以下のようにcustomというロガーを使用します。

_logger = logging.getLogger(f"custom.{__name__}")
_logger.info("ログを出力します。")

"custom"は今回log_conf.yamlで名付けた自作ロガー名で、その後の{name}とすることでファイル名が記述され、どのファイルから書き込まれたログなのかが分かるようになっています。

ログ設定を反映させてuvicornを起動

実行コマンドは以下のようになっています。

uvicorn main:app --reload --host 0.0.0.0 --port 8000 --log-config log_conf.yaml

Dockerを使っている場合は、Dockerfileやdocker-compose.yamlのcommandに記述しましょう！

おわりに

yamlでのlog定義、慣れれば非常に簡単で再利用も効いて誰が定義しても同じ記述になって、とても良い印象でした。元はマルチプロセスでのログ設定のため仕方なくという思いで使ってみましたが、マルチプロセス関係なく使用するのも全然有りだと思いました。

参考

Python logging 複数プロセスからのアクセスについてhttps://docs.python.org/ja/3/howto/logging-cookbook.html#logging-to-a-single-file-from-multiple-processes