Pythonのlogging.getLogger()で作ったログのログレベルをDEBUGにしたら、外部パッケージのデバッグログが出力された件

タイトルが理解できた方はスルーしてください。もしどういうことかちょっとでも疑問に感じた方はお読みください。自分はこれを見落とし、ログ基盤に負荷を与えて痛い目にあいました。

論より証拠

import logging

import requests


handler = logging.StreamHandler()
handler.setLevel(logging.NOTSET)

formatter = logging.Formatter("%(name)s - %(levelname)s - %(message)s")
handler.setFormatter(formatter)

logger = logging.getLogger()
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)

logger.info("hello world")
requests.get("https://google.com")

これを実行すると、下記のようなログ出力が出ます。

urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): google.com:443
urllib3.connectionpool - DEBUG - https://google.com:443 "GET / HTTP/1.1" 301 220
urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): www.google.com:443
urllib3.connectionpool - DEBUG - https://www.google.com:443 "GET / HTTP/1.1" 200 None

requestsの設定は触っていないつもりなのに、requests（が内部で使っているurllib3）のデバッグログが出力されました！触ってないのに壊れた！

なぜこうなるのか

loggerは名前のprefixをもとにした親子関係をもつ

loggingのloggerには名前（name）をつけることができます。通常は慣例的に以下のようにして、アプリケーションに対して一意な名前をつけます。

logger = logging.getLogger(__name__)

loggingのloggerは名前のprefixで親子関係を構成します。なお、名前にNone（=未設定）あるいは空文字""を設定したloggerはルートロガーとよばれ、logging.rootと同一になります。

print(logging.getLogger() is logging.root)  # => True
print(logging.getLogger(None) is logging.root)  # => True
print(logging.getLogger("") is logging.root)  # => True

下記は、親子関係の一例です。

(root)
  ├─ foo
  │   ├─ foo.bar
  │   │   └─ foo.bar.piyo
  │   │       └─ foo.bar.piyo.hoge
  │   ├─ foo/bar
  │   └─ foobar
  └─ bar

子には親のhandlerが継承される

ここからが大事なのですが、親に設定したhandlerは子へ継承されます。例えば、上の例でfoo.barに設定されたhandlerはfoo.bar、foo.bar.piyo、foo.bar.piyo.hogeの3つのloggerに設定されることになります。実際、下記のコードを実行することで確認できます。

import logging
import time


loggers = {}
names = [None,
           "foo",
             "foo.bar",
               "foo.bar.piyo",
                 "foo.bar.piyo.hoge",
             "foo/bar",
             "foobar",
           "bar"
         ]
for name in names:
    logger = logging.getLogger(name=name)
    logger.setLevel(logging.INFO)
    loggers[name] = logger


formatter = logging.Formatter("%(name)s - %(levelname)s - %(message)s")
handler = logging.StreamHandler()
handler.setFormatter(formatter)
loggers["foo.bar"].addHandler(handler)

# foo.bar, foo.bar.piyo, foo.bar.piyo.hogeからのみHello worldされる
for name in names:
    loggers[name].info(f"Hello world from {name}")

下記が出力です。

foo.bar - INFO - Hello world from foo.bar
foo.bar.piyo - INFO - Hello world from foo.bar.piyo
foo.bar.piyo.hoge - INFO - Hello world from foo.bar.piyo.hoge

子のログレベルを明示しない場合、親のログレベルが適用される

子のログレベルを明示的に設定している場合、親のログレベルが継承されることはありませんが、子のログレベルを設定していない場合、親のログレベルが適用されます。

以下の例をみてください。

import logging
import time


loggers = {}
names = [None,
           "foo",
             "foo.bar",
               "foo.bar.piyo",
                 "foo.bar.piyo.hoge",
             "foo/bar",
             "foobar",
           "bar"
         ]
for name in names:
    logger = logging.getLogger(name=name)
    if name == "foo.bar":
        logger.setLevel(logging.DEBUG)
    else:
        logger.setLevel(logging.INFO)
    loggers[name] = logger


formatter = logging.Formatter("%(name)s - %(levelname)s - %(message)s")
handler = logging.StreamHandler()
handler.setFormatter(formatter)
loggers["foo.bar"].addHandler(handler)

for name in names:
    loggers[name].debug(f"Hello world from {name}")

出力は下記になります。foo.barだけログレベルがDEBUGで、それ以外はINFOなので、debug出力はfoo.barからのみでます。

foo.bar - DEBUG - Hello world from foo.bar

一方、foo.bar以外のログレベルを設定しないときはどうでしょうか。

import logging
import time


loggers = {}
names = [None,
           "foo",
             "foo.bar",
               "foo.bar.piyo",
                 "foo.bar.piyo.hoge",
             "foo/bar",
             "foobar",
           "bar"
         ]
for name in names:
    logger = logging.getLogger(name=name)
    if name == "foo.bar":
        logger.setLevel(logging.DEBUG)
    # else:
    #     logger.setLevel(logging.INFO)
    loggers[name] = logger


formatter = logging.Formatter("%(name)s - %(levelname)s - %(message)s")
handler = logging.StreamHandler()
handler.setFormatter(formatter)
loggers["foo.bar"].addHandler(handler)

for name in names:
    loggers[name].debug(f"Hello world from {name}")

これを実行すると下記のような出力になり、foo.barとその子のログレベルがDEBUGになっていることが見て取れます。

foo.bar - DEBUG - Hello world from foo.bar
foo.bar.piyo - DEBUG - Hello world from foo.bar.piyo
foo.bar.piyo.hoge - DEBUG - Hello world from foo.bar.piyo.hoge

タイトル解題

Pythonのlogging.getLogger()で作ったログのログレベルをDEBUGにしたら、外部パッケージのデバッグログが出力された件

本記事タイトル

以上で説明した仕組みを念頭に入れれば、タイトルの挙動は明らかです。以下のような機序になります。

1. logging.getLogger()で作ったロガーはnameが指定されていないのでルートロガーであり、すべてのログの親である

2. ルートロガーのログレベルをDEBUGにすると、ログレベルを明示しない子のロガーのログレベルもDEBUGになる

3. 外部パッケージも含めて、ログレベルを明示しない子のロガーからDEBUG以上のレベルのログが出される

おわりに

ゆるふわ気分でloggingをつかっていて痛い目にあいました。loggingは案外複雑な挙動をするのでお気をつけください。

合同会社 nouu