• 2023/08/11

Pythonのロギングでハマった話

こんにちは。

今回は最近Pythonのロギングでハマったのでその内容を書きたいと思います。

Webサービスを運用する上で何かしらのログは、ほぼ100%取っていると思います。

ログを蓄積させていく中で開発する側として考えるべきポイントは多くありますが、その中でもログの出力先は大切です。

今回はログの出力先でハマった話を書きます。

前提

今回のケースでは、コンテナ環境で動いているWebアプリケーションを想定しています。

Dockerを利用している場合、コンテナ内で動作しているアプリケーションのログは標準出力を使うことが多いと思います。

これは、Dockerが標準出力をログとして認識してくれるため、例えば docker logs コマンドを使ってログを参照することができます。

また、Webアプリケーションなので、リクエストのログを取得しています。

リクエストのログなどは自分で取得するものやフォーマットを決めることもできますが、便利なライブラリを使うことも多いと思います。

今回のケースでもいい感じにログ出力してくれるライブラリを利用しています。

また、ログの出力単位を変えたいこともあります。

例えば特定のケースでは標準出力ではなく、ログファイルとして出力したいケースなどが考えられるでしょう。

今回も特定のケースでログをファイル出力する処理がありました。

事象

事象としては標準出力して欲しいログが全てファイルに出力されており、標準出力されていないという事象が発生しました。

Pythonの標準ライブラリのロギングで標準出力させたい場合は

import logging
import sys

logging.basicConfig(stream=sys.stdout, level=logging.INFO)
logger = logging.getLogger(__name__)

logger.info("abc")

のような形でログの出力ができます。

ファイル出力させたい場合は、

import logging

logging.basicConfig(filename="/var/log/xxx/xxx.log", filemode="a", format="%(message)s", level=logging.INFO)
logger = logging.getLogger(__name__)

logger.info("abc")

のようにするとファイルにログを出力することができます。

しかし、これがハマったポイントでした。

原因

logging.basicConfig は名前から察する通り、共通の設定です。

そのため、ロギングの種類が複数ある場合に使ってしまったため、一方のログ出力が意図しない形で出力されてしまっていました。

調査していく過程で、loggerの設定箇所で設定し直すということもできません。

できない例

import logging
import sys

logging.basicConfig(stream=sys.stdout, level=logging.INFO)
stdout_logger = logging.getLogger("stdout-logger")

logging.basicConfig(filename="/var/log/xxx/xxx.log", filemode="a", format="%(message)s", level=logging.INFO)
file_logger = logging.getLogger("file-logger")

また、使っているライブラリ でも内部的にbasicConfigの設定内容が採用されるようでさらに混乱をきたしました。 (ライブラリの設定で標準出力にしているのにファイル出力される！)

解決方法

logging.basicConfigを使わないで出力先を設定する方法に書き直すことで解決しました。

import logging
import sys

# 標準出力用ロガー
handler = logging.StreamHandler(sys.stdout)
formatter = logging.Formatter("%(message)s")
handler.setFormatter(formatter)
stdout_logger = logging.getLogger("stdout-logger")
stdout_logger.setLevel(logging.INFO)
stdout_logger.addHandler(handler)

# ファイル出力用ロガー
handler = logging.FileHandler("/var/log/xxx/xxx.log", mode="a")
formatter = logging.Formatter("%(message)s")
handler.setFormatter(formatter)
file_logger = logging.getLogger("file-logger")
file_logger.setLevel(logging.INFO)
file_logger.addHandler(handler)

最後に

今回は最近ハマってしまったPythonのログ出力について書きました。

ネットで検索するとbasicConfigで設定する方法がたくさんヒットするため、もしかしたらbasicConfigを使っても複数の設定ができる方法があるのかも知れませんが、見つけられませんでした。

とは言え、ロガーの設定は最初のみのため、あえてbasicConfigを使って設定する必要もないのかなとも思います。

こういうバグは原因の特定に時間がかかりますね。。