🦔

pythonのlogging関連まとめ

2022/03/25に公開

Python

logging

tech

はじめに

ファイルにログを出力したいし、開発中ならコンソールにも同じログを出力したい。
本番環境なら、ログファイルだけにしてログレベルも調整して…ということをしたくなる。

ロギングの方法について、まとめてみました。

loggingの動作についてを書いていくので、こういう情報を出したほうがいいとか、ログ設計については特に触れないです。

簡単なログ出力サンプル

まず大まかな設定ファイルと、ログ出力をザックリ見せます。
最低限の記載はあるので、あとは要件に合わせて適宜修正してください。
この例では、コンソールとapp.logのファイルへログ出力しています。

後半のほうに載せる、設定例と組み合わせて要件に合うように修正してもらえればと思います。

設定ファイル(.json)

{
  "version":1,
  "disable_existing_loggers": false,
  "formatters": {
    "simple": {
      "format": "%(asctime)s %(name)s:%(lineno)s %(funcName)s [%(levelname)s]: %(message)s"
    }
  },

  "handlers": {
    "consoleHandler": {
      "class": "logging.StreamHandler",
      "level": "DEBUG",
      "formatter": "simple",
      "stream": "ext://sys.stdout"
    },

    "fileHandler": {
      "class": "logging.FileHandler",
      "level": "DEBUG",
      "formatter": "simple",
      "filename": "app.log",
      "encoding": "utf-8"
    }
  },

  "loggers": {
    "hogeLogger": {
      "level": "DEBUG",
      "handlers": ["consoleHandler", "fileHandler"]
    },
    "fooLogger": {
      "level": "DEBUG",
      "handlers": ["consoleHandler", "fileHandler"]
    }
  },
  "root": {
    "level": "ERROR"
  }
}

ログを出力する

from logging import getLogger, config
import json

with open("設定ファイル(json)のファイルパス") as f:
    config.dictConfig(json.load(f))

logger = getLogger("hogeLogger")

if __name__ == "__main__":
    logger.debug("debug message")
    logger.info("info message")
    logger.warning("warning message")
    logger.error("error message")
    logger.critical("critical message")

設定ファイルの説明

基本は、formatter、handler、loggerなので、これを押さえとけば大体理解できると思う。主要な設定のみ解説。

formatter
出力メッセージの書式を決める
handler
ログの出力方法を決める。
ログをどこに出力するか？ファイルだったらそのファイル名は？とか
logger
loggerくんは、どのhandlerを使ってログ出力するかを決める。
handlerは複数選択できるので、同時に複数のファイルに出力することもできる。

もっと詳しく正しく知りたい場合は・・・

formatter

サンプルでは、simple とうい名前の書式を１つ定義しています。

format

出力したいログの書式を定義します。

出力できる変数は
LogRecord 属性
で確認できるので、出力させたいものを選ぶ。

後ろのsの意味を知りたい場合は、
printf 形式の文字列書式化
を参照。（参考：桁数調整したり、左寄せしたりの調整もできます)

datefmt

日時の出力フォーマットを変更したい場合に指定します。

datefmt 引数のフォーマットは、 time.strftime() でサポートされているものと同じです。

※参考：日時の書式を変更して、ミリ秒まで出力する

handlers

サンプルではコンソールに出力する用のconsoleHandlerと、ファイル出力用のfileHandlerという名前で2つのHandlerを定義しています。

class

利用するhandelerクラスを指定します。ライブラリとして、いろいろ用意されているので

を参考にする。

上の例では、コンソールに出力するStreamHandler と FileHandlerを取り上げました。
コンソール出力の場合は、コピペでOKだし、ファイル出力の場合もファイル名とエンコーディングぐらいしか変更するところはないです。

そのほか、細かい設定はそれぞれのhandlerクラスのドキュメント参照

format

formattersで定義したフォーマットの名前を指定してます。

level

ログの出力レベルを指定します。
(詳細は、ログレベルについて参照)

logger

サンプルでは、hogeLoggerとfooLoggerという名前のロガーを定義しています。
getLogger("ロガー名") で呼び出したロガー名と一致したロガーを使ってログ出力が実行されます。

level

ログの出力レベルを指定します。
(詳細は、ログレベルについて参照)

handlers

上で定義したhandlerの名前を設定する。ここには、複数のhandlerを設定できる。サンプルでは、標準出力と、ファイル出力のハンドラーを両方指定している。

root

rootロガーの設定です、下記のような書き方をした場合にrootロガーが使われます。

from logging import getLogger
logging.info("message") # loggingパッケージをで直接読んだり

logger = getLogger() # ロガー取得の時に、引数指定しなかったり
logger.info("message")

基本的に、こういう使い方はしないほうがいいので、別にrootの設定はいらない気がする。
設定できる内容はloggerと同一です。何かしらメッセージが出てしまう場合に備えて、rootロガーってわかるようなメッセージの書式を設定しといたほうがいいかも。

なぜrootロガーを使わないほうがいいかは

を参照

disable_existing_loggers

False固定で問題ないと思う。

これは、設定ファイルを読み込む際にそれより以前に取得したロガーの値を無効かするフラグ。
Trueになってると、実行順番で出力されなくなる場合があるので必要がなければFalseにしていいんじゃないかと思う。

詳しくは

ログレベルについて

設定したlevel以上のログを出力するように設定できます。設定したレベルと同等以上の優先度のログが出力されます。

ログレベルの優先順位は
DEBUG < INFO < WARNING < ERROR < CRITICAL
です。

例えば、ログレベルがWARNINGだった場合

logger.debug("debug")
logger.info("info")
logger.warning("warning")
logger.error("error")
logger.critical("critical")

warning、error、criticalが出力されます

なんでログレベルが設定できる箇所が複数あるの？

handlerとしてのログレベルと、loggerとしてのログレベルを分けら細かく設定できるからです。

っと、こんなことを文章で聞いてもピンとこないので、こういう想定の場合という例は
をいくつか出してみようと思います。

コンソール出力の量を制限したい

コンソールに出し過ぎると、動作が遅くなって検証に差し支える場合がある。その時は、warning以上を出すようにして、何か出たらログファイルのほうを確認してというようにしたい。

一部抜粋

"handlers": {
    "consoleHandler": {
      "class": "logging.StreamHandler",
      "level": "WARNING",
    },
    "fileHandler": {
      "class": "logging.FileHandler",
      "level": "INFO",
    }
  },
  "loggers": {
    "hogeLogger": {
      "level": "INFO",
      "handlers": ["consoleHandler", "fileHandler"]
    }

こうすると、ログファイルにはINFO以上のログ、コンソールにはWARNING以上のログが出力されます。

逆にローカル環境で開発中にコンソールにすべてのログを出したいって時は、loggerとconsoleHandlerのログレベルをDEBUGにすればよいです。

エラーログを別ファイルに同時に出力したい

ログ検知して自動で通知する運用をする場合、エラーログのみを出力するファイルがあると便利。

ログ検知してくれる製品では、特定の文字列が出力したら検視してくれるものもある。ただ、エラーログファイルで検知させる仕組みのほうが単純だし、製品を使わなくても自前で実装できる（更新日見るだけなので）

一部抜粋

"handlers": {
    "fileHandler": {
      "class": "logging.StreamHandler",
      "level": "INFO",
      "filename": "app.log",
    },
    "efileHandler": {
      "class": "logging.FileHandler",
      "level": "ERROR",
      "filename": "error.log",
    }
  },
  "loggers": {
    "hogeLogger": {
      "level": "INFO",
      "handlers": ["fileHandler", "efileHandler"]
    }

このようにすると、app.logにはINFO以上のログが出力され、error.logにはERROR以上のログが出力されるようになります。

それぞれでログレベルを設定できると、細かく制御しやすいってのを理解してもらえるかなと思います。

動的に設定を変更する

設定ファイルの中身を動的に変更したい場合は、下記のようにする。基本的に、設定ファイルのキー値で設定できるので特に難しいことはないと思う。

from datetime import datetime
from logging import getLogger, config
import json

with open("..\config\log_config.json") as f:
    log_conf = json.load(f)
    log_conf["handlers"]["fileHandler"]["filename"] = \
        '{}.logs'.format(datetime.utcnow().strftime("%Y%m%d%H%M%S"))
    config.dictConfig(log_conf)


logger = getLogger("hogeLogger")

if __name__ == "__main__":
    logger.debug("debug message")
    logger.info("info message")
    logger.warning("warning message")
    logger.error("error message")
    logger.critical("critical message")

stacktraceを出力したい

exc_infoの引数を渡してあげるだけ

if __name__ == "__main__":
    try:
        a =1 / 0
    except Exception:
        logger.error("error message", exc_info=True)

実行結果

2022/03/25 21:27:54.818 hogeLogger:14 [ERROR   ]: error message
Traceback (most recent call last):
  File "C:\Users\xxxxx\myproject\log_sample.py", line 12, in <module>
    a =1 / 0
ZeroDivisionError: division by zero

stack_infoというのもあるらしいが、自分の求める出力内容ではなかったので・・・・
詳細は下記参照

ロガーの設定を階層構造にする(ロガー名のベストプラクティス)

getLogger("ロガー名")で固定文字列を渡していた。あまり大きくなく、ツール的に使う分にはこれでも問題ない。ただ、より細かくログの出し分けを柔軟にさせたい場合とかは、ロガーに階層構造を持たせた方がよい。

logger = getLogger(__name__)

としてロガーを取得するのが、ベストプラクティスとされている。

これの何がうれしいかは、

ロガー名=モジュールパスとなってわかりやすい。
モジュール単位でのログ出し分けが可能になる
上位の設定が下位の階層に一律適用される
ライブラリ側が対応しといてくれると、利用者側でログの出し分けができる(SQLAlchemyのSQL実行ログを出力参考)

とか、ありそうだがピンとこないので、設定ファイルを見比べてみる。

一部抜粋

  "loggers": {
    "__main__": {
      "level": "INFO",
      "handlers": ["consoleHandler", "fileHandler"]
    },
    "db": {
      "level": "INFO",
      "handlers": ["consoleHandler", "fileHandler"]
    },
    "db.hoge": {
      "level": "WARNING"
    },
    "db.sub.hogehoge": {
      "level": "ERROR"
    }
  }

dbパッケージの各処理を呼んだ時のログを想定しています。
db.hoge、db.sub.hogehogeはなくても別にいいです。その場合、dbロガーの設定がパッケージの下位モジュールすべてに適用されます。

実行結果

2022/03/25 22:54:47.160 __main__:13 [INFO    ]: START
2022/03/25 22:54:47.160 db.hoge:8 [WARNING ]: hoge warning message
2022/03/25 22:54:47.160 db.hoge:9 [ERROR   ]: hoge error message
2022/03/25 22:54:47.161 db.sub.hogehoge:9 [ERROR   ]: hogehoge error message
2022/03/25 22:54:47.161 __main__:16 [INFO    ]: END

モジュール単位でログレベルを調整した結果は上記のような感じです

階層構造にしたら、ログが何個も出てきた

下記のような感じでログ設定していたとします。
設定意図としては、dbパッケージは、標準出力だけとりあえずする。db.hogeパッケージ以下からログファイルにも出力するようにする。

その場合は、"propagate": falseを設定する

詳細は下記参照

一部抜粋

 "loggers": {
    "__main__": {
      "level": "INFO",
      "handlers": ["consoleHandler", "fileHandler"]
    },
    "db": {
      "level": "INFO",
      "handlers": ["consoleHandler"]
    },
    "db.hoge": {
      "level": "INFO",
      "handlers": ["consoleHandler", "fileHandler"],
      "propagate": false
    },
    "db.sub.hogehoge": {
      "level": "INFO"
    }
  },

実行結果("propagate"なし)

2022/03/25 23:03:57.413 __main__:13 [INFO    ]: START
2022/03/25 23:03:57.413 db.hoge:7 [INFO    ]: hoge info message
2022/03/25 23:03:57.413 db.hoge:7 [INFO    ]: hoge info message
2022/03/25 23:03:57.414 db.hoge:8 [WARNING ]: hoge warning message
2022/03/25 23:03:57.414 db.hoge:8 [WARNING ]: hoge warning message
2022/03/25 23:03:57.414 db.hoge:9 [ERROR   ]: hoge error message
2022/03/25 23:03:57.414 db.hoge:9 [ERROR   ]: hoge error message
2022/03/25 23:03:57.414 db.sub.hogehoge:7 [INFO    ]: hogehoge info message
2022/03/25 23:03:57.414 db.sub.hogehoge:8 [WARNING ]: hogehoge warning message
2022/03/25 23:03:57.414 db.sub.hogehoge:9 [ERROR   ]: hogehoge error message
2022/03/25 23:03:57.414 __main__:16 [INFO    ]: END

実行結果("propagate"あり)

2022/03/25 23:08:03.973 __main__:13 [INFO    ]: START
2022/03/25 23:08:03.973 db.hoge:7 [INFO    ]: hoge info message
2022/03/25 23:08:03.973 db.hoge:8 [WARNING ]: hoge warning message
2022/03/25 23:08:03.973 db.hoge:9 [ERROR   ]: hoge error message
2022/03/25 23:08:03.973 db.sub.hogehoge:7 [INFO    ]: hogehoge info message
2022/03/25 23:08:03.973 db.sub.hogehoge:8 [WARNING ]: hogehoge warning message
2022/03/25 23:08:03.973 db.sub.hogehoge:9 [ERROR   ]: hogehoge error message
2022/03/25 23:08:03.973 __main__:16 [INFO    ]: END

ログファイル設定例

上のサンプルを基に、修正して設定例をいくつか載せます。

ログレベルの表示の桁数を合わせる

もっとも単純なログ出力で、日時、ログレベル、メッセージのみを表示した場合

デフォルト

2022-03-24 21:05:05,693 [DEBUG]: debug message
2022-03-24 21:05:05,693 [INFO]: info message
2022-03-24 21:05:05,693 [WARNING]: warning message
2022-03-24 21:05:05,693 [ERROR]: error message
2022-03-24 21:05:05,693 [CRITICAL]: critical message

こんな感じで、ログレベルでぐちゃっとなって、メッセージの開始位置がばらばらでなんとなく汚いので、↓のようにすると、桁がそろう

"simple": {
  "format": "%(asctime)s [%(levelname)-8s]: %(message)s"
}

変更後

2022-03-24 21:06:26,068 [DEBUG   ]: debug message
2022-03-24 21:06:26,068 [INFO    ]: info message
2022-03-24 21:06:26,068 [WARNING ]: warning message
2022-03-24 21:06:26,068 [ERROR   ]: error message
2022-03-24 21:06:26,068 [CRITICAL]: critical message

日時の書式を変更して、ミリ秒まで出力する

datefmtを指定すれば、日時の書式を変更できます。
ただ、datefmtを指定するとミリ秒をどうやって出すんだろ？って少し嵌りました。（strftime()の書式には秒以下を出力する書式がない）

formatで、%(msecs)03dのようにしてミリ秒を出力するようにすればよいです。（マイクロ秒の上3桁）
datefmtだけで日時は完結しといてほしかった感はあるが…

"simple": {
  "format": "%(asctime)s.%(msecs)03d [%(levelname)s]: %(message)s",
  "datefmt": "%Y/%m/%d %H:%M:%S"
}

デフォルト

2022-03-24 21:00:07,113 [DEBUG]: debug message
2022-03-24 21:00:07,113 [INFO]: info message
2022-03-24 21:00:07,113 [WARNING]: warning message
2022-03-24 21:00:07,113 [ERROR]: error message
2022-03-24 21:00:07,113 [CRITICAL]: critical message

変更後

2022/03/24 20:52:33.833 [DEBUG]: debug message
2022/03/24 20:52:33.833 [INFO]: info message
2022/03/24 20:52:33.833 [WARNING]: warning message
2022/03/24 20:52:33.833 [ERROR]: error message
2022/03/24 20:52:33.833 [CRITICAL]: critical message

ログローテーション(容量)

一定のファイル容量でローテーションするようにします。

"rotatingFileHandler": {
  "class": "logging.handlers.RotatingFileHandler",
  "level": "DEBUG",
  "formatter": "simple",
  "filename": "app.log",
  "encoding": "utf-8",
  "maxBytes": 1048576,
  "backupCount": 3
}

maxBytesは、1ファイルの最大サイズを指定します。バイト単位です。
backupCountは、履歴として残すファイル数です。履歴を3つ残す指定をしているので
app.log、app.log.1、app.log.3、app.log.3のログが作成されます。

ログローテーション(日次)

指定した時間の間隔で、ローテーションします。

日付が変わったタイミングでローテーション

"timeRotatingFileHandler": {
  "class": "logging.handlers.TimedRotatingFileHandler",
  "level": "DEBUG",
  "formatter": "simple",
  "filename": "app.log",
  "encoding": "utf-8",
  "when": "D",
  "backupCount": 3
}

作成されるログファイルは、%Y-%m-%d_%H-%M-%Sで日付が付与されます。（whenの値によ切り詰め)

上記の場合だと、app.log、app.log.2022-03-23、app.log.2022-03-24、app.log.2022-03-25とログファイルが作られます。

2時間ごとにローテーション

"timeRotatingFileHandler": {
  "class": "logging.handlers.TimedRotatingFileHandler",
  "level": "DEBUG",
  "formatter": "simple",
  "filename": "app.log",
  "encoding": "utf-8",
  "when": "H",
  "interval": 2,
  "backupCount": 3
}

そのほか細かい設定を知りたい場合は、TimedRotatingFileHandlerを参照

SQLAlchemyのSQL実行ログを出力

SQLAlchemyとかの、DBライブラリだと
実行したSQLをログに記録したい！って場合がある。
こういう時にgetLogger(__name__)という指定するメリットが良くわかる。

一応、ライブラリのcreate_engineのechoにTrueを設定すればコンソールには出力されるようになる。

engine = create_engine("mysql://scott:tiger@hostname/dbname", encoding='latin1', echo=True)

っが、やっぱりファイルにも出力したいって場合は、下記のようにhandlersを設定してあげればよい。

logger設定

"sqlalchemy.engine.Engine": {
  "level": "INFO",
  "handlers": ["consoleHandler", "fileHandler"]
},

実行結果

2022-03-30 22:00:05.560 sqlalchemy.engine.Engine:136 [INFO]: BEGIN (implicit)
2022-03-30 22:00:05.563 sqlalchemy.engine.Engine:136 [INFO]: SELECT //**省略**//
FROM edinet_meta 
WHERE edinet_meta.xbrl_flg = %s AND edinet_meta.pdf_flg = %s AND edinet_meta.doc_type_cd IN (%s, %s)
2022-03-30 22:00:05.563 sqlalchemy.engine.Engine:136 [INFO]: [generated in 0.00032s] (1, 1, '350', '220')

おわりに

簡単にログについて書こうと思ったら、案外長くなった…

間違い等ありましたら、ご指摘お願いいたします。

はじめに

簡単なログ出力サンプル

設定ファイル(.json)

ログを出力する

設定ファイルの説明

formatter

format

datefmt

handlers

class

format

level

logger

level

handlers

root

disable_existing_loggers

ログレベルについて

なんでログレベルが設定できる箇所が複数あるの？

コンソール出力の量を制限したい

エラーログを別ファイルに同時に出力したい

動的に設定を変更する

stacktraceを出力したい

ロガーの設定を階層構造にする(ロガー名のベストプラクティス)

階層構造にしたら、ログが何個も出てきた

ログファイル設定例

ログレベルの表示の桁数を合わせる

日時の書式を変更して、ミリ秒まで出力する

ログローテーション(容量)

ログローテーション(日次)

SQLAlchemyのSQL実行ログを出力

おわりに

Discussion