MyEnigma

とあるエンジニアのブログです。#Robotics #Programing #C++ #Python #MATLAB #Vim #Mathematics #Book #Movie #Traveling #Mac #iPhone

初心者のためのPythonにおけるlogging入門


The Python 3 Standard Library by Example: Pyth 3 Stan Libr Exam _2 (Developer's Library) (English Edition)

目次

はじめに

自分以外の人に使用されるソフトウェアを開発している場合、

自分の手元では発生しない問題や、

たまにしか発生しない問題に悩まされることが多いと思います。

 

そんな場合は、手元で再現することができないので、

ソフトウェアにロガーを埋め込み、

その問題が発生した時のログファイルを元に

問題解決することになります。

 

そんな時に重要なのが、

元のソフトウェアを変更することなく、

必要な情報を得るためのロギング機能を実装することです。

 

今回の記事では、Pythonの標準ライブラリの一つである

ロギング機能用モジュールloggingの基本的な使い方や、

ユースケースに基づく、逆引きメモを紹介したいと思います。

docs.python.org

 

loggingモジュールの基本的な使い方

基本的には、下記の公式ドキュメントが最も参考になります。

docs.python.org

docs.python.org

docs.python.org

docs.python.org

 

コマンドラインからログのレベル変更

非常にシンプルなロガーの使い方として、

単体で動くPythonスクリプトを、

実行時の引数からロガーレベルを変更することを考えます。

 

残念ながら、loggingモジュールは、

実行時の引数から直接ロギングレベルを変更することはできないので、

同じ公式ライブラリであるargparseと併用すると便利です。

import logging
import argparse


def get_log_level_from_args():
    parser = argparse.ArgumentParser()
    parser.add_argument("--log", type=str, default="Warn")
    return logging.getLevelName(parser.parse_args().log.upper())


logging.basicConfig(level=get_log_level_from_args())

logging.debug('debug')
logging.info('info')
logging.warning('warning')
logging.error('error')
logging.critical('critical')

上記のコードのように、

argparseで取得した--logの値をbasicConfigに与えることで、

何も指定しないと、defaultのwarnレベル以上が表示されますが、

f:id:meison_amsl:20200411154715p:plain

--log=Debugを指定すると、すべてのレベルのログが表示されます。

f:id:meison_amsl:20200411155053p:plain

 

今回使用したbasicConfigにfilenameを指定することで、

ログをファイルに保存したり、

formatにログフォーマットを指定することで、

ログに時刻を追加することができます。

docs.python.org

 

モジュール毎のロガー設定とロギングレベルの変更

前述のbasicConfigを使うと、

実行しているすべてのロガーのログレベルを変更してしまいます。

もし、規模の大きいシステムを開発している時は、

あるモジュールのみのロガーレベルを変更してデバックをしたくなります。

そんなときは、それぞれのモジュール個別のロガーを設定しておくと、

モジュール毎にログレベルやログの設定を変更できます。

 

例えば、moduleA.pyとmoduleB.pyを下記のようにします。

moduleA.py

from logging import getLogger, StreamHandler
logger = getLogger(__name__)
handler = StreamHandler()
logger.addHandler(handler)
logger.propagate = False


def process():
    logger.debug('debug')
    logger.info('info')
    logger.warning('warning')
    logger.error('error')
    logger.critical('critical')

moduleB.py

from logging import getLogger, StreamHandler
logger = getLogger(__name__)
handler = StreamHandler()
logger.addHandler(handler)
logger.propagate = False


def process():
    logger.debug('debug')
    logger.info('info')
    logger.warning('warning')
    logger.error('error')
    logger.critical('critical')

そして、これら2つのモジュールを利用するスクリプトがある場合、

下記のように、あるモジュールだけのログレベルを変更することができます。

from logging import getLogger, DEBUG

import moduleA
import moduleB

print("======")
moduleA.process()
print("======")
moduleB.process()

# Only change moduleA logger level
alogger = getLogger("moduleA")
alogger.setLevel(DEBUG)

print("======")
moduleA.process()
print("======")
moduleB.process()

上記を実行すると、

片方のモジュールだけログレベルを変更できます。

f:id:meison_amsl:20200411203704p:plain

 

ちなみに、getLoggerで渡すロガーの名前が同じ場合、

同じ名前のloggerの参照が渡されます。

これにより、複数のモジュールから一つのロガーに

ログを送信することが可能です。

 

加えて、loggingのログ出力機能は、

スレッドセーフです。

したがって、単一プロセスの複数のスレッドから

一つの出力先にログを出力することができます。

 

しかし、複数のプロセスから、

一つのファイルに書き込むことはできないため、

そのような場合は、SocketやHTTPのHandlerを使うか、

QueueHandlerを使って、Queue Comsumterとして

ログを保存させる必要があります。  

loggingのhandler

Pythonのloggingで混乱しやすい所は、handlerだと思います。

 

このhandlerは、それぞれのloggerにaddHandler()やremoveHandler()で

複数設定でき、それぞれのhandlerの設定方法によって、

別々のログの処理を実施することができます。

 

それぞれのhandlerは個別のロガーレベルを持っているため、

例えば、一つのloggerで、

  • info以上のログは標準出力に

  • warn以上のログはファイル保存し、

  • critical以上のログはメール送信する

といったような、設定をすることができます。

また、それぞれのhandlerにformatterを設定できるので、

それぞれのログのフォーマットを別々に設定することができます。

 

loggingで使えるhandler

下記は代表的なloggingのハンドラです。

ハンドラを受け取るハンドラなども存在します。

  • StreamHandler: 標準出力など、様々なストリームにログを出力

  • FileHandler: ファイルにログを出力

  • NullHandler: 何も出力しない (ライブラリなどで意図的にデフォルトでログを出力したくない時に使います)

  • RotatingFileHandler: ログファイルのサイズをベースにRotateするログファイルを出力

  • TimedRotatingFileHandler: ロギングの時間をベースにRotateするログファイルを出力

  • WatchedFileHandler: newsyslogやlogrotateなどで変更されるログファイルにログを出力

  • SocketHandler: ログをTCPソケットベースで送信

  • DatagramHandler: ログをUDPソケットベースで送信

  • SysLogHandler: ログをローカル or 遠隔のUnix syslogに出力

  • NTEventLogHandler: ログをWindows NT, 2000, Windows XP のイベントログに送信

  • SMTPHandle: ログをSMTPベースのメール送信

  • MemoryHandler: ログの内容を一度、メモリにバッファし、定期的に別のハンドラに送信

  • HTTPHandler: ログをHTTPのgetやpostで、HTTPサーバに送信

  • QueueHandler: 別スレッドでハンドラを実行するハンドラ

 

loggingモジュールで利用可能なhandlerは、

下記のAPIドキュメントから、参照できます。

docs.python.org

 

loggingのfilter

loggingのfilterは、ある条件にあったログのみを保存したり、

ログに、ログ出力した以外の情報を追加して、

ログ送信したいときに便利です。

例えば、passwordという文字列が入っているログを

保存 or 出力しないようにしたり、

複数のスレッドでログを出力したいときに、

スレッドの番号などをログに追加できます。

 

filterの設定は、logging.Filterを継承するクラスを作り、

そのクラスの中でログに含めるかを判断する

booleanを返すfilter関数を定義し、

ハンドラにaddFilter(filter)すればOKです。

 

from logging import Filter, INFO, basicConfig, getLogger

basicConfig(level=INFO)


class NoPasswordFilter(Filter):
    def filter(self, record):
        log_message = record.getMessage()
        return 'password' not in log_message


logger = getLogger(__name__)
logger.addFilter(NoPasswordFilter())
logger.info('User: tom')
logger.info('User: andy, password = pass')

上記のコードを実行すると、

passwordという文字が入っていないログだけが

表示されます。

 

設定ファイルによるロガーの設定

前述の通り、Pythonの標準ライブラリであるloggingを使えば、

非常に細かいロギングの設定が可能です。

 

しかし、デバックの際に、それぞれのモジュールのログレベルを制御するのに、

それぞれのモジュールのコードに設定を書き込むのは、大変な場合もありますし、

アプリケーション全体のロギングの設定を

一つの設定ファイルで管理したいときもあります。

 

そんなときは、logging.config.dictConfigの機能を使えば、

jsonやyamlファイルなどに書かれた、アプリケーション全体のロギング設定を

読み込むだけで、設定を変更することができます。

 

例えば、moduleAとmoduleBのソースコードそのものは、

下記のように、モジュール名を元にloggerを作って利用するだけにしておき、

from logging import getLogger

logger = getLogger(__name__)

def process():
    logger.debug('debug_A')
    logger.info('info_A')
    logger.warning('warning_A')
    logger.error('error_A')
    logger.critical('critical_A')
from logging import getLogger

logger = getLogger(__name__)

def process():
    logger.debug('debug_B')
    logger.info('info_B')
    logger.warning('warning_B')
    logger.error('error_B')
    logger.critical('critical_B')

下記のような、アプリケーション全体のロギング設定ファイルを作成します。

一つの設定ファイルにすべてのモジュールのロギングの設定や、

フォーマッタ、ハンドラを定義できます。

{
  "version": 1,
  "formatters": {
    "simple": {
      "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
    },
    "notime": {
      "format": "%(name)s - %(levelname)s - %(message)s"
    }
  },
  "handlers": {
    "console": {
      "class": "logging.StreamHandler",
      "level": "DEBUG",
      "formatter": "simple",
      "stream": "ext://sys.stdout"
    },
    "console_notime": {
      "class": "logging.StreamHandler",
      "level": "DEBUG",
      "formatter": "notime",
      "stream": "ext://sys.stdout"
    }
  },
  "loggers": {
    "moduleA": {
      "level": "DEBUG",
      "handlers": [
        "console"
      ],
      "propagate": "no"
    },
    "moduleB": {
      "level": "ERROR",
      "handlers": [
        "console_notime"
      ],
      "propagate": "no"
    }
  }
}

そして、アプリケーションの起動の最初で、

このファイルを読み込んで、

logging.config.dictConfigでロギングを設定すると、

from logging.config import dictConfig

import moduleA
import moduleB
import json

print("======")
moduleA.process()
print("======")
moduleB.process()

with open("logconf.json", "r") as f:
    dictConfig(json.load(f))

print("======")
moduleA.process()
print("======")
moduleB.process()

下記のように、

アプリケーション全体のロギング設定を変更できます。

f:id:meison_amsl:20200501113225p:plain

dictConfig関数は、Pythonの辞書型で設定が定義されていれば良いため、

辞書型に変換できるファイルであれば、

どんなファイルフォーマットでも設定ファイルとして利用できます。

 

また、このように設定ファイルとソースコードを

別ファイルとして管理することで、

プログラミングがわからない、利用者にでも

ロギングレベルを変更して、ログを取ってもらうことなどが

簡単に依頼できるようになります。

 

参考資料

ログ出力のための print と import logging はやめてほしい - Qiita

Python Logging Best Practices ~ Pieces of Mind

Pythonのロギングを覚えた - Qiita

Logging クックブック — Python 3.8.2 ドキュメント

myenigma.hatenablog.com

myenigma.hatenablog.com

myenigma.hatenablog.com

myenigma.hatenablog.com

myenigma.hatenablog.com


The Python 3 Standard Library by Example: Pyth 3 Stan Libr Exam _2 (Developer's Library) (English Edition)

 

MyEnigma Supporters

もしこの記事が参考になり、

ブログをサポートしたいと思われた方は、

こちらからよろしくお願いします。

myenigma.hatenablog.com