Python loggingで2回同じログが表示されてしまう

Question

#Python loggingで2回同じログが表示されてしまいます。

[実行結果]
Jul 1 00:01:02 testhost TEST3: テストメッセージ3
Jul 1 00:01:02 testhost 終了: 終了メッセージ
Jul 1 00:01:02 testhost 終了: 終了メッセージ

メッセージごとにファシリティを変更したいため、以下のコードを書きました。
もっとシンプルな方法があれば、ご教示お願いします。
※1つのファイルですべて記載したい
※コンフィグ用のファイルは作成したくない

#[test.py]

# -*- coding: utf-8 -*-
import sys
from logging import getLogger,Formatter,DEBUG
from logging.handlers import SysLogHandler


# ログ設定①
def log_init1():
    logger = getLogger(__name__)
    logger.setLevel(DEBUG)
    handler = SysLogHandler(address="/dev/log", facility=SysLogHandler.LOG_LOCAL2)
    handler.setLevel(DEBUG)
    handler.setFormatter(Formatter("%(message)s"))
    logger.addHandler(handler)
    return logger


# ログ設定②
def log_init2():
    logger = getLogger(__name__)
    logger.setLevel(DEBUG)
    handler = SysLogHandler(address="/dev/log", facility=SysLogHandler.LOG_LOCAL3)
    handler.setLevel(DEBUG)
    handler.setFormatter(Formatter("%(message)s"))
    logger.addHandler(handler)
    return logger

# ログ設定さん
def log_init3():
    logger = getLogger(__name__)
    logger.setLevel(DEBUG)
    handler = SysLogHandler(address="/dev/log", facility=SysLogHandler.LOG_LOCAL4)
    handler.setLevel(DEBUG)
    handler.setFormatter(Formatter("%(message)s"))
    logger.addHandler(handler)
    return logger


def output_message(key):

    key = int(key)

    if key == 1:
        logger = log_init1()
        logger.error("TEST1: テストメッセージ1")
    elif key == 2:
        logger = log_init1()
        logger.error("TEST2: テストメッセージ2")
    else:
        logger = log_init2()
        logger.error("TEST3: テストメッセージ3")

    logger = log_init3()
    logger.error("終了: 終了メッセージ")


def main():

    key = sys.argv[1]
    output_message(key)

if __name__ == "__main__":
    main()


#python3 test.py 3

#[実行結果]
#Jul  1 00:01:02 testhost TEST3: テストメッセージ3
#Jul  1 00:01:02 testhost 終了: 終了メッセージ
#Jul  1 00:01:02 testhost 終了: 終了メッセージ

Answer 1

pythonのloggingのgetLoggerは同じインスタンスを返す仕様になっています。

https://docs.python.org/ja/3/library/logging.html

ロガーを直接インスタンス化することは 絶対に してはならず、常にモジュール関数 logging.getLogger(name) を介してインスタンス化することに注意してください。 同じ name で getLogger() を複数回呼び出すと、常に同じロガー・オブジェクトへの参照が返されます。

なので同じロガーに対して、 logger.addHandler(handler) を2度呼び出すと2回ハンドラーで処理されることになります。
実際にやっている箇所は、if-elif-else文のいずれかで1回目、終了メッセージの前に2回目ですね
なので、終了メッセージだけ2回表示されています。

初期化作業はプログラム全体で1回だけ呼び出されるように修正すればよいかと思います。
その代わり、ロガーを使う側はgetLogger()のみ行うようにします。

ロガーを使う側は初期化の方式が選べなくなりますが、逆を言えば初期化に気にすることなく使えるようになります。
それでも、もし選びたい場合は、ロガーを初期化するときとロガーを使う時でgetLogger("mylogger1")、getLogger("mylogger2")等のように別名で呼び出せばよいかと思います。

ただ、pythonのloggingのロガーは他のライブラリでも使われる想定で作られており、モジュール毎に出力をコントロールするなどの機能が備わったりしています。
そのため、この挙動を理解しておかないと、うっかり他のモジュールで使われている名前を使ってしまい、急に他のモジュールのログが出てくるなどの思わぬ動作をしてびっくりするかもしれません。
なので、できれば理解して使うことをお勧めします。

Comments

[ITOMO5963]

ご回答ありがとう。
対処は、どのようにしたら、良いでしょうか？

[fukasawah]

「初期化作業は～」のところで書いてるつもりです

[退会済みユーザー]

fukusawah様が仰られているような内容です。
https://qiita.com/kujira_go/items/a005e928bea428a7f6cd
globalでloggerをキー管理しているところです。
私はいつもこの方法使います。

[ITOMO5963]

ありがとうございます