Python のロギングを完全に理解する

はじめに

• 言うまでもありませんがここでいう「完全に理解」はダニング＝クルーガー的な意味で申し上げております。ご了承下さい。

今回の内容を3行でいうと

• Pythonのロギング(loggingパッケージ）の公式ドキュメントがどうも読みづらくてとっつきにくい
• とは言え実用的なものを作るにはロギングの理解は必須
• そこで調べてみました。その内容。

と言うものになります。これを読めばとりあえずPythonのロギングについて何も知らない状態から、必要な最低限のことはわかったというところまで行けるものを目指しました。丁寧にやったので少し長くなりましたが内容は難しくありません。Pythonの実行環境がある方は実際にソースをコピペして動かしてみると理解が深まると思います。

今回使用したPythonのバージョン

コンソール

>python --version
Python 3.10.5

なぜ import logging をしてはいけないのか。

• Pythonと言う言語はよくできた言語で、やりたいことはたいていできかつなるべく簡単にできるようになっていて、Javaみたいに理屈っぽくないし、JavaScript みたいに自由過ぎて困るということもない、 名前の通り男らしくてすっきりした言語です。ところがロギングに関してはPythonにしては珍しくちょっとわかりづらい状況になっているようです。
• Pythonのロギングについて調べてみると、こういう記事があったりします。

• print()をむやみに使うなというのはわかるのですが、入門書みると大抵載っている import logging を使うなとはどういうことなのでしょうか。記事を読むと、どうもこういうことのようです。
• 【要約】logging.debug() などで使われるのはルートロガーと呼ばれるグローバルな（すべてのモジュールから共有される）資源であるため、これを使うと他のパッケージやモジュールに影響を与えかねない。そこいらの１モジュールごときが安易に使って良いものではない。基本動作として logging.getLogger(__name__) を使って自分用のロガーを作成して影響範囲を限定するべき。
• 読解まちがってたらごめんなさいなのですが、だいたいそういうことなのではないかと思います。
• やっちゃいけないということはわかったけれど、じゃあどうすればいいんですかという話になります。
• 結局公式ドキュメント↓をちゃんと読めということなのですが、どうもこれ読んだだけだと頭にすっと入ってこないので、整理してみたいと思います。

まずは無設定でログ出力してみる。

• 本来はログの出力に関する設定をプログラムの初期処理でいろいろやるのが正しい在り方ですが、この初期設定というのがログシステムの全体像をだいたい掴んでからでないと何をやっているのかよくわかりません。そこで今回はあくまで理解を深めるために実験的に、敢えてそういう初期設定をすっとばして無設定＝デフォルトの状態から動かしてみます。

logging.debug()などを使う。

• ログを出す方法として一番シンプルなのは、logging パッケージにもとから定義されているグローバルな debug()やinfo()を使ってログ出力することです。

moduleA.py

import logging
logging.debug("debug")
logging.info("info")
logging.warning("warning")
logging.error("error")
logging.fatal("fatal")
logging.critical("critical")

■ 実行結果

PS C:\> python .\moduleA.py
WARNING:root:warning
ERROR:root:error
CRITICAL:root:fatal
CRITICAL:root:critical

• この場合、loggingパッケージ内でデフォルトで用意されているルートロガー(logging.root)を経由してコンソールへログ出力されます。
• debug()とinfo() のログが出力されないのはrootロガーの初期状態でのログレベルがWARNINGだからです。
• ログレベルについてですが、logging内に定義されているPythonのログシステムでのログレベルの序列は、下記の通りです（JavaのLog4Jなどと同様の考え方です）。ログレベルとは、いわばログ出力時にその値以上のログが出力される閾値のようなものです。ロガーに設定したログレベルを上げるにしたがって、それ以下のログは出なくなり、より重要なログ（値の大きいレベルのログ）だけが出力されるようになります。一般的には、開発時にはログレベルを下げてたくさん情報を出して置き、運用に入ったらログレベルを上げて細かい情報は出さなくします。

logging/__init__.py

CRITICAL = 50
FATAL = CRITICAL
ERROR = 40
WARNING = 30
WARN = WARNING
INFO = 20
DEBUG = 10
NOTSET = 0

• これを見ると、実はPythonではCRITICALとFATALは内部的に同じものであることがわかります。またWARNとWARNINGも同じ意味になります。

ルートロガーを直接使う。

• さて、logging.xxx() でルートロガーが使われているならば下記のようにしても同じことになるはずです。

moduleA.py

from logging import root
root.debug("debug")
root.info("info")
root.warning("warning")
root.error("error")
root.fatal("fatal")
root.critical("critical")

■ 実行結果

PS C:\> python .\moduleA.py
warning
error
fatal
critical

• ところが、先ほどは出力行にログレベルとロガー名らしき情報が出ていたのに出てこなくなってしまいました。これはなぜかというと、logging.warning()などを呼んだときにルートロガーにハンドラ（ハンドラが何かについては後述します）が設定されていない場合、デフォルトのフォーマット設定をするため暗黙のうちに logging.basicConfig() という関数が呼ばれてフォーマットを設定していたからです。root.warning()を直接呼ぶとこの関数が呼ばれないため、rootロガーが用意している最低限の出力しかされないわけです。

basicConfig()を呼んでみる。

• そこで今度はあらかじめ logging.basicConfig() を呼んでみましょう。

moduleA.py

from logging import root,basicConfig
basicConfig()
root.debug("debug")
root.info("info")
root.warning("warning")
root.error("error")
root.fatal("fatal")
root.critical("critical")

■ 実行結果

WARNING:root:warning
ERROR:root:error
CRITICAL:root:fatal
CRITICAL:root:critical

• basicConfig()内でフォーマットが設定され、期待していた結果になりました。
• ちなみにこのとき使われるフォーマットはlogging内で下記のように定義されています。

logging/__init__.py

BASIC_FORMAT = "%(levelname)s:%(name)s:%(message)s"

ルートロガーのログレベルを設定する。

• 今度はいったんbasicConfig()を外してルートロガーのログレベルを DEBUGレベルにしてみます。

moduleA.py

from logging import root,DEBUG
root.setLevel(DEBUG)
root.debug("debug")
root.info("info")
root.warning("warning")
root.error("error")
root.fatal("fatal")
root.critical("critical")

■ 実行結果

PS C:> python .\moduleA.py
warning
error
fatal
critical

• ログレベルをDEBUGにしたらdebug()やinfo()も出力されるかと思いきや、されませんでした。これは、無設定状態でのrootロガーにはログのハンドラが設定されていないことが原因です。ハンドラとは、発生したログをどう取り扱って出力するか（ファイルに出力する、標準出力に出力する、標準エラーへ出力する、特定のソケットへ送るなど）その出し先を設定するクラスで、本来はプログラムの最初でロガーに初期設定しておくべきものです（今回は実験のためわざとその設定を省いています）。

lastResortハンドラ

• それならば、なぜwarning以降のログは表示されるのでしょうか。それは、ルートロガーにハンドラ設定が無かった場合、logging.lastResort と呼ばれるデフォルトのハンドラにログ情報が渡され、このハンドラ経由で出力が行われるためです。last resortとは、最後の楽園というよりは大学受験のときの「すべり止め」みたいな意味合いがあります。他が全部ダメでも最後にはこれがある、みたいなニュアンスを含んだ名前です。
• lastResort ハンドラーはloggingパッケージ内でこのように初期化されています。

logging/__init__.py

_defaultLastResort = _StderrHandler(WARNING)
lastResort = _defaultLastResort

• lastResortの実体は _StderrHandler クラスのインスタンスで、このハンドラのログレベルがWARNING となっています。そのため、ロガーでログレベルをDEBUGに設定しても、ハンドラ側のログレベルがWARNINGであるため、DEBUG とINFO のログはハンドラ側でせきとめられて出力されないのです。ロガーにもハンドラにもログレベルがあるというのは冗長な設計のように感じるかもしれませんが、そうなっている理由は後で考察します。
• いずれにせよ、ロガーだけでなくハンドラにもログレベルの設定があるので、そちらもDEBUGレベルにしないとlogging.debug()の出力はされないようです。設定してみます。

moduleA.py

from logging import root,DEBUG,lastResort
root.setLevel(DEBUG)
lastResort.setLevel(DEBUG)
root.debug("debug")
root.info("info")
root.warning("warning")
root.error("error")
root.fatal("fatal")
root.critical("critical")

■ 実行結果

PS C:\> python .\moduleA.py
debug
info
warning
error
fatal
critical

• 想定通りdebug()まで出力されました。改めてフォーマットも設定してみます。

moduleA.py

from logging import root,DEBUG,lastResort, Formatter, BASIC_FORMAT
root.setLevel(DEBUG)
lastResort.setLevel(DEBUG)
lastResort.setFormatter(Formatter(BASIC_FORMAT))
root.debug("debug")
root.info("info")
root.warning("warning")
root.error("error")
root.fatal("fatal")
root.critical("critical")

■ 実行結果

PS C:> python .\moduleA.py
DEBUG:root:debug
INFO:root:info
WARNING:root:warning
ERROR:root:error
CRITICAL:root:fatal
CRITICAL:root:critical

• これで想定通り、DEBUGログ以上の出力が行われました。
• しかし、これではまだ、コンソールにログが出ているだけで、print()とたいして変わりません。通常はログはログファイルとしてファイル出力することが多いと思います。今出力がコンソールに出ているのは、先ほどみたように、logging.lastResort ハンドラとして_StderrHandlerが設定されているため、出力の向き先が標準エラー出力になっているからです。したがって、ログをファイルに出したければ logging.lastResort にファイルハンドラを設定すれば良さそうだと言うことがわかると思います。

ためしにlastResortを挿げ替えてみる。

• それでは、実際にやってみます。

moduleA.py

from logging import root,DEBUG,lastResort, Formatter, BASIC_FORMAT, FileHandler
import logging
root.setLevel(DEBUG)
logging.lastResort = FileHandler('test.log')
logging.lastResort.setLevel(DEBUG)
logging.lastResort.setFormatter(Formatter(BASIC_FORMAT))
root.debug("debug")
root.info("info")
root.warning("warning")
root.error("error")
root.fatal("fatal")
root.critical("critical")

■ 実行結果

PS C:\> python .\moduleA.py
PS C:\> type .\test.log
DEBUG:root:debug
INFO:root:info
WARNING:root:warning
ERROR:root:error
CRITICAL:root:fatal
CRITICAL:root:critical

• lastResort をFileHandler に挿げ替えたのでログ内容はコンソールには出力されなくなり、 test.log に出力されました。

しかし、勿論こんなことをしてはいけない。

• 最初の方で掲載しておいた記事の通りです。ルートロガーやlastResortハンドラはライブラリであるloggingパッケージ内にあるグローバル変数であり、このような共有資源に対して自分の作ったプログラムの都合だけでログレベルを変更したりハンドラを設定してデフォルト動作を変更したりするのはNGです。他のフレームワークやライブラリでこれらの共有資源は参照されているかもしれないからです。数十行～数百行くらいの小さなプログラムでrootロガーを使うくらいは良いかもしれませんが、logging.lastResortを勝手にいじるなんていうのはいかにもまずそう、というのが普通の感覚だと思います。より本格的なアプリケーションであればいよいよそんなことはしてはいけないと考えるべきでしょう。

自前のハンドラを設定する。

• ルートロガーを使うのはまだ良いとして、ハンドラを設定せずに lastResort で出力しているのは通常ありえない状態なので、まじめに自分でハンドラを用意し、ルートロガーへ追加します。それから、ルートロガーを使う場合はrootをimportするのではなく、logging.getLogger() で取得するのが普通です。getLogger() の引数はロガー名ですが、引数なしで呼べばルートロガーを取得できますのでそのように直してみます。また、Loggerには hasHandlers() というメソッドがあり、そのロガーにハンドラが付与されているかどうかを判定することができます。戻り値はboolです。これを呼んで、ハンドラが付与されたことを確認するログを出してみます。

moduleA.py

from logging import DEBUG,Formatter, BASIC_FORMAT, FileHandler, Logger
import logging
logger:Logger = logging.getLogger()
logger.setLevel(DEBUG)
logging.lastResort.setLevel(DEBUG)
# ロガーにハンドラがあるかどうか調べる
logger.debug(f"ハンドラの有無（１回目）：{logger.hasHandlers()}")
fh:FileHandler = FileHandler('test.log') # 自前のハンドラを追加
fh.setFormatter(Formatter(BASIC_FORMAT)) # 自前のハンドラにフォーマットを設定
fh.setLevel(DEBUG)
logger.addHandler(fh)
# もう一度ロガーにハンドラがあるかどうか見る
logger.debug(f"ハンドラの有無（２回目）：{logger.hasHandlers()}")

■ 実行結果

PS C:\> python .\moduleA.py
ハンドラの有無（１回目）：False
PS C:\> type .\test.log
DEBUG:root:ハンドラの有無（２回目）：True

• 自前のファイルハンドラ fh をルートロガーに紐づけています。ロガーにハンドラが紐づいたので lastResort は使われなくなり、2回目のdebug()ログはログファイルに出力されているのがわかると思います

ルートロガーに自前のハンドラをもう１つ追加し、ファイルとコンソールの両方にログ出力する。

• ルートロガーに自前のファイルハンドラを紐づけた結果、コンソールにはログが出力されなくなってしまいました。ファイルにログ出力したのはいいけど、コンソールにも出したい場合もあるのではないかと思います。実はここまで書いていなかったのですが、１つのロガーに対してハンドラは複数紐づけることが可能です。ファイルハンドラとは別にコンソールに出力するハンドラも紐づけると、ロガーに与えられたログイベントは紐づけられたハンドラそれぞれに同じ内容が送られます。このことを利用して、コンソールとファイルの両方にログを出してみます。

moduleA.py

from logging import DEBUG,Formatter, BASIC_FORMAT, FileHandler, Logger, StreamHandler
import logging
logger:Logger = logging.getLogger()
logger.setLevel(DEBUG)
logging.lastResort.setLevel(DEBUG)
# ロガーにハンドラがあるかどうか調べる
logger.debug(f"ハンドラの有無（１回目）：{logger.hasHandlers()}")

# ファイルハンドラの紐づけ
fh:FileHandler = FileHandler('test.log') # 自前のハンドラを追加
fh.setFormatter(Formatter(BASIC_FORMAT))
fh.setLevel(DEBUG)
logger.addHandler(fh)

# コンソールに出力するハンドラの紐づけ
ch = StreamHandler()
ch.setLevel(DEBUG)
logger.addHandler(ch)

# もう一度ロガーにハンドラがあるかどうか見る
logger.debug(f"ハンドラの有無（２回目）：{logger.hasHandlers()}")

■ 実行結果

PS C:\> python .\moduleA.py
ハンドラの有無（１回目）：False
ハンドラの有無（２回目）：True
PS C:\> type .\test.log
DEBUG:root:ハンドラの有無（２回目）：True

• ここまでくると、ログレベルをロガーとハンドラの両方で設定できることの意味が分かってくると思います。もしログレベル設定がロガー側だけにしかなかったら、紐づいているハンドラ全てについてログを出すか、逆に全て出さないかの2択になってしまいます。ハンドラ側にもログレベルがあると、あるハンドラでは DEBUG レベルとし、あるハンドラでは INFO レベルとする、というような細かい設定が可能になります。まとめてログレベルを変えたいときはロガー側で、個別のハンドラだけログレベルを変えたいときはハンドラ側で設定すればよいわけです。また、すでにお気づきの方もいると思いますが、フォーマッタもハンドラごとに設定できるため、それぞれのハンドラごとに書式を別にすることが可能です。実際、上の例ではコンソールには単純にprint() と同じように出力し、ファイルにはログレベルとロガー名が出力されるような書式になっています。

ルートロガーを使うのをやめて、自前のロガーを作って使う。

• このあたりでそろそろルートロガーに直接出力するのはやめていきましょう。
• 自前のロガーに切り替えるのは簡単で、logging.getLogger()をするときにロガーに自分用の名前をつければよいだけです。
• なお、今まではコンソールに出すときは何も情報を付与していませんでしたが、今回はどのロガーのログ出力なのかわかるようにすべてのハンドラーで出力が行われたロガーの名前を出すようにハンドラ設定します。

moduleA.py

from logging import (
    DEBUG,
    Formatter,
    BASIC_FORMAT,
    FileHandler,
    Logger,
    StreamHandler,
    getLogger,
    lastResort,
)

logger: Logger = getLogger("hoge")
logger.setLevel(DEBUG)
lastResort.setLevel(DEBUG)
lastResort.setFormatter(Formatter(BASIC_FORMAT))  
# ロガーにハンドラがあるかどうか調べる
logger.debug(f"ハンドラの有無（１回目）：{logger.hasHandlers()}")

# ファイルハンドラの紐づけ
fh: FileHandler = FileHandler("test.log")  # 自前のハンドラを追加
fh.setFormatter(Formatter(BASIC_FORMAT))
fh.setLevel(DEBUG)
logger.addHandler(fh)

# コンソールに出力するハンドラの紐づけ
ch = StreamHandler()
ch.setFormatter(Formatter(BASIC_FORMAT))
ch.setLevel(DEBUG)
logger.addHandler(ch)

# もう一度ロガーにハンドラがあるかどうか見る
b: bool = logger.hasHandlers()
logger.debug(f"ハンドラの有無（２回目）debugレベル：{b}")
logger.info(f"ハンドラの有無（２回目）infoレベル：{b}")
logger.warning(f"ハンドラの有無（２回目）warningレベル：{b}")

■ 実行結果

PS C:\> python .\moduleA.py
DEBUG:hoge:ハンドラの有無（１回目）：False
DEBUG:hoge:ハンドラの有無（２回目）debugレベル：True
INFO:hoge:ハンドラの有無（２回目）infoレベル：True
WARNING:hoge:ハンドラの有無（２回目）warningレベル：True
PS C:\> type test.log
DEBUG:hoge:ハンドラの有無（２回目）debugレベル：True
INFO:hoge:ハンドラの有無（２回目）infoレベル：True
WARNING:hoge:ハンドラの有無（２回目）warningレベル：True

• どのログも hogeロガーから出力されたものであることがわかります。当然、rootロガーからの出力は使われなくなっています。
• ここで、ちょっと気になることがあります。先ほどの公式サイトの説明では、自前のロガー（今回でいうとhogeロガー）はルートロガーを親とするツリー構造に組み込まれ、ルートロガーに対する子ロガーになるはずです。公式ドキュメントには下記のようなフローがありました。
  
• これを見る限り、子ロガーで出力をした後、propagate プロパティがTrueであれば（デフォルトではTrue）、親ロガーへログ出力が伝播するはずです。この場合の親ロガーとは、ルートロガーです。子ロガーである hoge ロガーからルートロガーへ伝播されたはずのログ出力(LogRecord)はどうなったのでしょうか？
• ここで思い出すべきは、ルートロガーに対してはハンドラをまったく設定していないことです。ハンドラをまったく設定していない場合はlastResortハンドラへログ出力が送られて出力されていました。しかし今回の場合は、子ロガーであるhogeロガーにハンドラを設定して、そこから出力が行われています。つまり、lastResort はルートロガーだけでなく、その下にぶら下がっているすべての子ロガーも含めて、ロガーツリー内のどこかでハンドラが設定されていれば、使われないと言うことなのだと思います。

ルートロガーにもハンドラを設定してみる。

• もしそうならば、ルートロガーに対して明示的にハンドラを設定してやれば、そちらからもログが出るはずです。やってみます。

moduleA.py

from logging import (
    DEBUG,
    Formatter,
    BASIC_FORMAT,
    FileHandler,
    Logger,
    StreamHandler,
    getLogger,
    lastResort,
)

# lastResortハンドラの設定
lastResort.setLevel(DEBUG)
lastResort.setFormatter(Formatter(BASIC_FORMAT))

# ルートロガーにもハンドラを紐づけてみる
rlogger: Logger = getLogger()
ch = StreamHandler()
ch.setFormatter(Formatter("これはルートロガーのハンドラです。→" + BASIC_FORMAT))
ch.setLevel(DEBUG)
rlogger.addHandler(ch)
rlogger.warning("ルートロガーへの出力")

# 自前ロガー
logger: Logger = getLogger("hoge")
logger.setLevel(DEBUG)

# ロガーにハンドラがあるかどうか調べる
logger.debug(f"ハンドラの有無（１回目）：{logger.hasHandlers()}")

# ファイルハンドラの紐づけ
fh: FileHandler = FileHandler("test.log")  # 自前のハンドラを追加
fh.setFormatter(Formatter(BASIC_FORMAT))
fh.setLevel(DEBUG)
logger.addHandler(fh)

# コンソールに出力するハンドラの紐づけ
ch2 = StreamHandler()
ch2.setFormatter(Formatter("これはhogeロガーのハンドラです。→" + BASIC_FORMAT))
ch2.setLevel(DEBUG)
logger.addHandler(ch2)

# もう一度ロガーにハンドラがあるかどうか見る
b: bool = logger.hasHandlers()
logger.debug(f"ハンドラの有無（２回目）debugレベル：{b}")
logger.info(f"ハンドラの有無（２回目）infoレベル：{b}")
logger.warning(f"ハンドラの有無（２回目）warningレベル：{b}")

■ 実行結果

PS C:\> python moduleA.py
これはルートロガーのハンドラです。→WARNING:root:ルートロガーへの出力
これはルートロガーのハンドラです。→DEBUG:hoge:ハンドラの有無（１回目）：True
これはhogeロガーのハンドラです。→DEBUG:hoge:ハンドラの有無（２回目）debugレベル：True
これはルートロガーのハンドラです。→DEBUG:hoge:ハンドラの有無（２回目）debugレベル：True
これはhogeロガーのハンドラです。→INFO:hoge:ハンドラの有無（２回目）infoレベル：True
これはルートロガーのハンドラです。→INFO:hoge:ハンドラの有無（２回目）infoレベル：True
これはhogeロガーのハンドラです。→WARNING:hoge:ハンドラの有無（２回目）warningレベル：True
これはルートロガーのハンドラです。→WARNING:hoge:ハンドラの有無（２回目）warningレベル：True
PS C:\> type .\test.log
DEBUG:hoge:ハンドラの有無（２回目）debugレベル：True
INFO:hoge:ハンドラの有無（２回目）infoレベル：True
WARNING:hoge:ハンドラの有無（２回目）warningレベル：True

• 想定通りの結果となりました。最初にルートロガーから出した出力と、その次にhogeロガーから出した出力「ハンドラの有無（１回目）」はルートロガーのハンドラから出力されています。最初にルートロガーから出した出力がルートロガーのハンドラで処理されるのは当然ですし、その次にhogeロガーから出したログはhogeロガーにハンドラがない状態で出していますので、hogeロガーではハンドルされず、ルートロガーに伝播した後でルートロガーのハンドラから出力されています。
• その後にhogeロガーから出したログはhogeロガーにハンドラを設定した後に出しているので、hogeロガーのハンドラとルートロガーのハンドラの両方から出力され、２行ずつ出力されているのがわかると思います。
• 一方、test.log へ出力するハンドラは hogeロガーにしか設定していませんので、１行ずつ出力されています。

では、モジュールがもう一つ増えたらどうなるのか？

• この状態から、さらにmoduleB.py を作り、そこでさらに自前ロガーを作ったらどうなるのでしょうか。やってみます。
• 出力が増えてきたのでそれぞれの出力を見分けやすいように「●ｎ」という番号をつけてみます。

moduleA.py

from logging import (
    DEBUG,
    Formatter,
    BASIC_FORMAT,
    Logger,
    StreamHandler,
    getLogger,
    lastResort,
)
import moduleB

# lastResortハンドラの設定
lastResort.setLevel(DEBUG) 
lastResort.setFormatter(Formatter(BASIC_FORMAT))

# ルートロガーにもハンドラを紐づけてみる
rlogger: Logger = getLogger()
ch = StreamHandler()
ch.setFormatter(Formatter("これはルートロガーのハンドラです。→" + BASIC_FORMAT))
ch.setLevel(DEBUG)
rlogger.addHandler(ch)
rlogger.warning("●１．ルートロガーへの出力")

# 自前ロガー
logger: Logger = getLogger("hoge")
logger.setLevel(DEBUG)

# ロガーにハンドラがあるかどうか調べる
logger.debug(f"●２．hogeロガーのハンドラの有無（１回目）：{logger.hasHandlers()}")

# コンソールに出力するハンドラの紐づけ
ch2 = StreamHandler()
ch2.setFormatter(Formatter("これはhogeロガーのハンドラです。→" + BASIC_FORMAT))
ch2.setLevel(DEBUG)
logger.addHandler(ch2)

# もう一度ロガーにハンドラがあるかどうか見る
b: bool = logger.hasHandlers()
logger.debug(f"●３．hogeロガーのハンドラの有無（２回目）debugレベル：{b}")

# 他のモジュールのログを呼び出す
moduleB.out_log()

moduleB.py

from logging import (
    DEBUG,
    Logger,
    getLogger,
)

# 自前ロガーその２
logger: Logger = getLogger("fuga")
logger.setLevel(DEBUG)
logger.warning("●０．fugaロガーを作りました。")

def out_log() -> None:
    # ロガーにハンドラがあるかどうか調べる
    logger.debug(f"●４． fugaロガーのハンドラの有無：{logger.hasHandlers()}")

■ 実行結果

PS C:\> python .\moduleA.py
●０．fugaロガーを作りました。
これはルートロガーのハンドラです。→WARNING:root:●１．ルートロガーへの出力
これはルートロガーのハンドラです。→DEBUG:hoge:●２．hogeロガーのハンドラの有無（１回目）：True
これはhogeロガーのハンドラです。→DEBUG:hoge:●３．hogeロガーのハンドラの有無（２回目）debugレベル：True
これはルートロガーのハンドラです。→DEBUG:hoge:●３．hogeロガーのハンドラの有無（２回目）debugレベル：True
これはルートロガーのハンドラです。→DEBUG:fuga:●４． fugaロガーのハンドラの有無：True

• 「●0」のログでfugaロガーの作られるタイミングを確認しました。moduleA.py での import moduleB のタイミングであることがわかります。この出力は lastResortハンドラから出ていますが、まだハンドラにフォーマッタを設定する前なので単純にメッセージだけが出ています。
• moduleB.py 内で作成した fuga ロガーにはハンドラを何も設定していませんでしたがこのロガーから出力したログはルートロガーのハンドラから出力されています（●４）。やはりルートロガーが親になっていると考えられます。
• ちょっと不思議なのは、fugaロガーのハンドラの有無がTrueなことです（●４）。どうやら自分でハンドラを持っていなくても、親のロガーがハンドラを持っていれば hasHandlers() の戻り値はTrue になるようです。
• fugaロガーをhogeロガーの子供（ルートロガーの孫）にするにはどうしたらよいでしょうか？ドキュメントによれば、ロガー名をピリオドで区切って階層化してやれば孫ロガーにすることができそうです。やってみます。ついでにこの孫ロガーにもハンドラを設定してみます。

moduleB.py

from logging import (
    BASIC_FORMAT,
    DEBUG,
    Formatter,
    Logger,
    StreamHandler,
    getLogger,
)

# 自前ロガーその２
logger: Logger = getLogger("hoge.fuga")
logger.setLevel(DEBUG)
logger.warning("●０．hoge.fugaロガーを作りました。")


def out_log() -> None:
    ch = StreamHandler()
    ch.setFormatter(Formatter("これはhoge.fugaロガーのハンドラです。→" + BASIC_FORMAT))
    logger.addHandler(ch)
    # ロガーにハンドラがあるかどうか調べる
    logger.debug(f"●４． hoge.fugaロガーのハンドラの有無：{logger.hasHandlers()}")

■ 実行結果

●０．hoge.fugaロガーを作りました。
これはルートロガーのハンドラです。→WARNING:root:●１．ルートロガーへの出力
これはルートロガーのハンドラです。→DEBUG:hoge:●２．hogeロガーのハンドラの有無（１回目）：True
これはhogeロガーのハンドラです。→DEBUG:hoge:●３．hogeロガーのハンドラの有無（２回目）debugレベル：True
これはルートロガーのハンドラです。→DEBUG:hoge:●３．hogeロガーのハンドラの有無（２回目）debugレベル：True
これはhoge.fugaロガーのハンドラです。→DEBUG:hoge.fuga:●４． hoge.fugaロガーのハンドラの有無：True
これはhogeロガーのハンドラです。→DEBUG:hoge.fuga:●４． hoge.fugaロガーのハンドラの有無：True
これはルートロガーのハンドラです。→DEBUG:hoge.fuga:●４． hoge.fugaロガーのハンドラの有無：True

• ルートロガーの孫であるhoge.fugaロガーからのログ出力は親である hogeロガーから、およびさらにその親であるルートロガーからも出力されました。想定通りです。
• hoge.fugaロガーにはログレベルを設定するのを忘れましたが、ハンドラにログレベルが設定されていない場合は、結びついているロガーのログレベルとみなされるようです。
• ルートロガーに影響を与えたくない場合は、hogeロガーからルートロガーへの伝播を切れば良いはずです。そのためにはhogeロガーのpropagateプロパティをFalseにすれば良さそうです。やってみます。

ルートロガーへのログの伝播を切る

moduleA.py

from logging import (
    DEBUG,
    Formatter,
    BASIC_FORMAT,
    Logger,
    StreamHandler,
    getLogger,
    lastResort,
)
import moduleB

# lastResortハンドラの設定
lastResort.setLevel(DEBUG) 
lastResort.setFormatter(Formatter(BASIC_FORMAT))  

# ルートロガーにもハンドラを紐づけてみる
rlogger: Logger = getLogger()
ch = StreamHandler()
ch.setFormatter(Formatter("これはルートロガーのハンドラです。→" + BASIC_FORMAT))
ch.setLevel(DEBUG)
rlogger.addHandler(ch)
rlogger.warning("●１．ルートロガーへの出力")

# 自前ロガー
logger: Logger = getLogger("hoge")
logger.setLevel(DEBUG)
logger.propagate = False  # ルートロガーへの伝播を断ち切る

# ロガーにハンドラがあるかどうか調べる
logger.debug(f"●２．hogeロガーのハンドラの有無（１回目）：{logger.hasHandlers()}")

# コンソールに出力するハンドラの紐づけ
ch2 = StreamHandler()
ch2.setFormatter(Formatter("これはhogeロガーのハンドラです。→" + BASIC_FORMAT))
ch2.setLevel(DEBUG)
logger.addHandler(ch2)

# もう一度ロガーにハンドラがあるかどうか見る
b: bool = logger.hasHandlers()
logger.debug(f"●３．hogeロガーのハンドラの有無（２回目）debugレベル：{b}")

# 他のモジュールのログを呼び出す
moduleB.out_log()

■ 実行結果

●０．hoge.fugaロガーを作りました。
これはルートロガーのハンドラです。→WARNING:root:●１．ルートロガーへの出力
DEBUG:hoge:●２．hogeロガーのハンドラの有無（１回目）：False
これはhogeロガーのハンドラです。→DEBUG:hoge:●３．hogeロガーのハンドラの有無（２回目）debugレベル：True
これはhoge.fugaロガーのハンドラです。→DEBUG:hoge.fuga:●４． hoge.fugaロガーのハンドラの有無：True
これはhogeロガーのハンドラです。→DEBUG:hoge.fuga:●４． hoge.fugaロガーのハンドラの有無：True

• hogeロガーのpropagateをFalseにしたのでそれ以降のルートロガーのハンドラからの出力はされなくなっています。
• 「●２」のログが出ているのが不思議に感じるかもしれませんが、これはルートロガーのハンドラからではなく、lastResort から出ています（lastResortはルートロガーに紐づいているわけではなく、どのロガーからも独立している特殊なハンドラです）。通常、ハンドラがまったく見つからないということはありえないのでlastResortからの出力を気にする必要はないわけですが、それでも気になって lastResort からの出力を抑えたい場合は、lastResortのログレベルを上げるか、lastResort として NullHandler を挿げ替えて設定してやると良いです。
• 孫ロガーであるhoge.fugaロガーからの出力は親のhogeロガーのハンドラからは出力されていますが、ルートロガーのハンドラからは出なくなったことがわかると思います。
• ここまで調べてきた結果で、ロガーが設定によってどのように動作するかがほぼ確認できたと思います。わかったことを改めて整理してみます。

ここまででわかったことのまとめ

• ロガーには出力先に応じたハンドラを複数紐づけすることができる。ハンドラがまったく紐づけられていない場合はlogging.lastResortハンドラへログが送られるが、その場合このハンドラのログレベルはデフォルトで WARNING なのでdebug()やinfo()のログ出力はされない。
• ハンドラには種類があり、また独自のフォーマットを(Formatterによって）設定することができる。
• logging.getLogger()に自分が使いたいロガー名を渡すとその名前を持った自分用のロガーが作成され、そのロガーはルートロガーの下へツリー状に紐づけられる。このとき、ツリーの構造はロガー名の中にピリオドを含むことで多段階に階層化することができる。
• ツリー内の任意のロガーへ出力を行うとそのロガーを起点にロガーツリーを上まで（根元まで）たどりながらそれぞれのロガーに紐づくハンドラがあればそのハンドラに対して出力が行われる。
• ロガーツリーの伝播を途中で止めたければ止めたい位置のロガーのpropagateプロパティをFalseにしてやれば、そこから上へは伝播されない。
• ロガーツリーをたどった結果、その途中でハンドラを持つロガーが一つもなかった場合、ログは lastResort へ送られる。
• ということで以下、本記事の総括をします。

【結論】それで、結局どうしたらいいの？

以上を踏まえての結論としては、以下の通りです。

• グローバルな資源であるルートロガーやlastResortの設定はなるべく触らない。特になんらかのフレームワークやライブラリを使っていて、それらがルートロガーを使う可能性がある場合は触るべきではない。
• したがってlogging.debug()などのルートロガーを使うログ出力メソッドは基本動作として使わない。ただ数十行～数百行程度の小さなスクリプトで、分かった上でルートロガーを使うくらいは別に構わないのではないか？とも思います。
• 通常のアプリでは、ロガーツリーの中で根本にあるロガー(状況に応じてルートロガーか、もしくはその子である自前ロガー）を一つ選んで、そこに必要なハンドラを設定し、その下にいる他のロガーからは上へ向かって（ツリーのルート方向へ向かって）ログを伝播させる。ツリーの途中にあるロガーにハンドラを設定する意味はあまりないように思われる。
• 普通のアプリでは複数の独自ロガーでツリーを作る意味はないのではないか？共有するモジュールに自分用のロガーを一つ作って、他のモジュールからはそれを参照して使えばよいのではないか。よほど大きいシステムでない限りそれだけで事足りるケースが大半なのではないかと思います。
• ハンドラをつけたロガーより上（ツリーの根本側）へログを伝播させたくなければpropagateプロパティにFalseを設定する。
• どういう事情があるのかわかりませんが、基本的にシンプルをよしとするPythonにしてはちょっと過剰な仕様だなぁと感じます（個人の感想です）。それがPythonのロギング設定をわかりにくくしているのだと思います。想像ですが、巨大なアプリではロガーツリーを機能ごとに用意して細かく出力制御したい、というような需要があるのかもしれません。例えば、アプリのアーキテクチャでDBアクセス層とビジネスロジック層、プレゼンテーション層みたいな区分けを作って、それぞれの層でロギングを別個に制御したい、というようなことが考えられます。そういう段階まで行ったらロギングチョットワカル的なステージへ進んでいくことになるでしょう。

---

以上、Pythonのロギングについて調査し、考えをまとめてみました。ここまで読んでいただき、ありがとうございました。この記事がどなたかのお役に立てば幸いです。