uvicorn にアプリのloggerがでなかったので python の logger を理解した

そうだ、logger 理解しよう

同僚から、FastApiでloggingするときはこうしないといけなかった、という話を聞いた

    logger = logging.getLogger('uvicorn')      # <---必ず 'uvicorn'

自分のを見たら、こうしてた

    logger = logging.getLogger(__name__)        # 新しく作って
    handler = logging.StreamHandler(sys.stdout) # stdout に出す

これって何が違うんだろう？ という疑問を調べてみた。

1. ただ logger を作るだけだと log に出ないサンプル

ここで使ったファイルはgithubに置きました。
https://github.com/kujiy/learn-uvicorn-logger/tree/master

main1

import uvicorn
import logging
import os

async def app(scope, receive, send):
    # ここは読み飛ばしてね ------->
    assert scope['type'] == 'http'
    await send({
        'type': 'http.response.start',
        'status': 200,
        'headers': [
            [b'content-type', b'text/plain'],
        ],
    })
    await send({
        'type': 'http.response.body',
        'body': b'Hello, world!',
    })
    # <---------

    logger = logging.getLogger(__name__)  #<---------------------------
    logger.info('info-test')

if __name__ == "__main__":
    uvicorn.run(f"{os.path.basename(__file__).removesuffix('.py')}:app", host="127.0.0.1", port=5000, reload=True, log_level="info")

起動してページを呼んで見る

$ python main1.py
$ curl -s http://127.0.0.1:5000/
Hello, world!

logがでない!

INFO:     Started server process [36930]
INFO:     Waiting for application startup.
INFO:     ASGI 'lifespan' protocol appears unsupported.
INFO:     Application startup complete.
INFO:     127.0.0.1:58119 - "GET / HTTP/1.1" 200 OK                                    (ここに出るはずなのに)   # <-----------------------

2. stdout を指定すると log が出る

loggerの出力先がイケてないと思われるので、stdoutを指定してみる。

main2

import uvicorn
import logging
import os
import sys

async def app(scope, receive, send):
    assert scope['type'] == 'http'
    await send({
        'type': 'http.response.start',
        'status': 200,
        'headers': [
            [b'content-type', b'text/plain'],
        ],
    })
    await send({
        'type': 'http.response.body',
        'body': b'Hello, world!',
    })

    logger = logging.getLogger(__name__)
    handler = logging.StreamHandler(sys.stdout)     # <-----------------------
    logger.addHandler(handler)
    logger.setLevel(logging.DEBUG)
    logger.info('info-test')

if __name__ == "__main__":
    uvicorn.run(f"{os.path.basename(__file__).removesuffix('.py')}:app", host="127.0.0.1", port=5000, reload=True, log_level="info")

logが出ました

INFO:     127.0.0.1:58181 - "GET / HTTP/1.1" 200 OK
info-test                                 # <-----------------------

3. uvicorn の logger を使う - これがシンプル

main3

import uvicorn
import logging
import os

async def app(scope, receive, send):
    assert scope['type'] == 'http'
    await send({
        'type': 'http.response.start',
        'status': 200,
        'headers': [
            [b'content-type', b'text/plain'],
        ],
    })
    await send({
        'type': 'http.response.body',
        'body': b'Hello, world!',
    })

    logger = logging.getLogger('uvicorn')      # <------------------------------
    logger.info('info-test')

if __name__ == "__main__":
    uvicorn.run(f"{os.path.basename(__file__).removesuffix('.py')}:app", host="127.0.0.1", port=5000, reload=True, log_level="info")

INFO:     127.0.0.1:58131 - "GET / HTTP/1.1" 200 OK
INFO:     info-test                    # <-----------------------

出ましたね。uvicorn logger を通せばもっとそれっぽいformatになると思ってたけど、違った。

さっきとの違いは log levelがあるかないかだけ。まあ、これでもきれいだ。

info-test              # 自前 stdout の logger
INFO:     info-test    # uvicorn のlogger

さて、このgetLogger('uvicorn') ってなんなんだろう。 。

ここから本題です。

uvicorn のloggerの仕組みを調査する

uvicornのソースを見てみます。

さっきのmain*.py は uvicorn.run() をcallしてるので、そこからおっていきます。

uvicorn.run()

まず 1 行目で Config を作ってます。

uvicorn/config.py

def run(app: typing.Union[ASGIApplication, str], **kwargs: typing.Any) -> None:
    config = Config(app, **kwargs)    #  <----------------
    server = Server(config=config)
    ...

https://github.com/encode/uvicorn/blob/b5af1049e63c059dc750a450c807b9768f91e906/uvicorn/config.py

uvicorn/Config

config.py の中には LOGGING_CONFIG があります。
ここで stdout と stderr への stream を定義しています

uvicorn/config.py

LOGGING_CONFIG: dict = {
    "version": 1,
    ...
    "handlers": {
        "default": {
            "formatter": "default",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stderr",  #     <----------------------------
        },
        "access": {
            "formatter": "access",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",      #     <----------------------------
        },
    },
    "loggers": {
        "uvicorn": {"handlers": ["default"], "level": "INFO"},
        "uvicorn.error": {"level": "INFO"},
        "uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False},
    },
}

https://github.com/encode/uvicorn/blob/b5af1049e63c059dc750a450c807b9768f91e906/uvicorn/config.py

これは Config.log_config という変数に入ります

config.py

class Config:
    def __init__(
        self,
        ...
        log_config: Optional[Union[dict, str]] = LOGGING_CONFIG,

おそらく Config() がするのはここまででしょう。次へ行きます　（後でconfigの重要な仕事が発覚します。さくっと次に行ったせいで遠回りしました）

次は Server() です

uvicorn/server.py

きっとこいつが logger を初期化しているはず！見てみよう！

uvicorn/server.py

def run(app: typing.Union[ASGIApplication, str], **kwargs: typing.Any) -> None:
    config = Config(app, **kwargs) 
    server = Server(config=config)   #  <----------------
    ...

https://github.com/encode/uvicorn/blob/b5af1049e63c059dc750a450c807b9768f91e906/uvicorn/server.py

と思ったら、 server.py の中はもう logger がsetされてる前提の様子

uvicorn/server.py

import logging
...
logger = logging.getLogger("uvicorn.error")

何も設定しなかったら出ないよね？の確認

main4.py

import logging

if __name__ == "__main__":
    logger = logging.getLogger(__name__)
    logger.info('info-test')

main5.py

import logging

if __name__ == "__main__":
    logger = logging.getLogger("uvicorn.error")
    logger.info('info-test')

どちらも何も出力されません。

そもそも logging.getLogger ってなんだっけ？

logging - python バンドルmodule

logging moduleを見に行きます

https://github.com/python/cpython/blob/main/Lib/logging/__init__.py

nameがない場合はrootを返してます。つまりなくても新しく作ってくれるのね。

logging/__init__.py

def getLogger(name=None):
    """
    Return a logger with the specified name, creating it if necessary.

    If no name is specified, return the root logger.
    """
    if not name or isinstance(name, str) and name == root.name:
        return root
    return Logger.manager.getLogger(name)

https://github.com/python/cpython/blob/main/Lib/logging/__init__.py

root は RootLogger.
root loggerは他のloggerと変わらない。違うのはlogging levelが必須なことと1つしか階層に存在できないことだ、と解説されています

class RootLogger(Logger):
    """
    A root logger is not that different to any other logger, except that
    it must have a logging level and there is only one instance of it in
    the hierarchy.
    """
    def __init__(self, level):
        """
        Initialize the logger with the name "root".
        """
        Logger.__init__(self, "root", level)

たしかに RootLoggerを作るときは WARNING = これがデフォルト値ってことか　で作ってます

root = RootLogger(WARNING)

Logger.init() を見ると説明がわかりやすい。

Logger classのインスタンスごとに logging channelが作られる。 1 logging channelは applicationの 1 エリアです。何を 1 area にするかはappliaction developerが決めます。logging channelは input という親を作ったら、input.csv input.xls のように dot で区切って階層を表します。

なるほど

__init__.py

class Logger(Filterer):
    """
    Instances of the Logger class represent a single logging channel. A
    "logging channel" indicates an area of an application. Exactly how an
    "area" is defined is up to the application developer. Since an
    application can have any number of areas, logging channels are identified
    by a unique string. Application areas can be nested (e.g. an area
    of "input processing" might include sub-areas "read CSV files", "read
    XLS files" and "read Gnumeric files"). To cater for this natural nesting,
    channel names are organized into a namespace hierarchy where levels are
    separated by periods, much like the Java or Python package namespace. So
    in the instance given above, channel names might be "input" for the upper
    level, and "input.csv", "input.xls" and "input.gnu" for the sub-levels.
    There is no arbitrary limit to the depth of nesting.
    """
    def __init__(self, name, level=NOTSET):
        """
        Initialize the logger with a name and an optional level.
        """
        Filterer.__init__(self)
        self.name = name
        self.level = _checkLevel(level)
        self.parent = None
        self.propagate = True
        self.handlers = []
        self.disabled = False
        self._cache = {}

uvicorn と思ったら gunicorn を見ていたの巻

uvicornに戻ります。 loggerを作ってる場所が見つからなかったんですが、handlers 的なので探してたらUvicornWorker にこれを見つけました。

handlers やlevelをsetupしてるようです。

workers.py

class UvicornWorker(Worker):
    """
    A worker class for Gunicorn that interfaces with an ASGI consumer callable,
    rather than a WSGI callable.
    """

    CONFIG_KWARGS = {"loop": "auto", "http": "auto"}

    def __init__(self, *args: Any, **kwargs: Any) -> None:
        super(UvicornWorker, self).__init__(*args, **kwargs)

        logger = logging.getLogger("uvicorn.error")
        logger.handlers = self.log.error_log.handlers          <--------------
        logger.setLevel(self.log.error_log.level)   
        logger.propagate = False

        logger = logging.getLogger("uvicorn.access")
        logger.handlers = self.log.access_log.handlers          <--------------
        logger.setLevel(self.log.access_log.level)
        logger.propagate = False

興味深いのはerror/accessどちらも logger という同じ変数名で書いてあるところ。 logger の uvicorn.access/error という２つの違うインスタンスを作って、以後はそれで分けてアクセスするからいいんですね。

ここで self.log を見ようとしたら、そもそも宣言がありません。

なぜか gunicorn の中へ迷い込む

UvicornWorker が継承している Worker を見ます。

from gunicorn.workers.base import Worker

gunicorn の中に来ました。uvicornよりgunicornのほうが先だったのか? （後でわかりますが、これは gunicorn ようのmoduleでした）

中を見ると・・くっ

gunicorn/workers/base.py

class Worker(object):
    ...
    def __init__(self, age, ppid, sockets, app, timeout, cfg, log):        #   <-----------
        """\
        This is called pre-fork so it shouldn't do anything to the
        current process. If there's a need to make process wide
        changes you'll want to do that in ``self.init_process()``.
        """
        ...
        self.alive = True
        self.log = log       #   <-----------

https://github.com/benoitc/gunicorn/blob/master/gunicorn/workers/base.py

ここで行き詰まります。UvicornWorkerをコールしてる場所がわからん。ここじゃなかったか・・

gunicornの中にはこうやって呼ぶらしいことを書いてるmdがあった。gunicornから初期化されるのか。これはgunicorn用のやつなのか

gunicorn -w 4 -k uvicorn.workers.UvicornWorker

Config()に戻る

よく見たら、config で init して configure_logging() してたわ・・・

class Config:
    def __init__(
        self,
        ...
        この間100行
        ...
        self.configure_logging()           # <----------------------

どうsetupしてるかというと、最初に作った log_config をそのまま読ませてました。ここで stdout が uvicorn.access に setされる仕組み。

config.py

    def configure_logging(self) -> None:
        logging.addLevelName(TRACE_LOG_LEVEL, "TRACE")

        if self.log_config is not None:
            if isinstance(self.log_config, dict):
                if self.use_colors in (True, False):
                    self.log_config["formatters"]["default"][
                        "use_colors"
                    ] = self.use_colors
                    self.log_config["formatters"]["access"][
                        "use_colors"
                    ] = self.use_colors
                logging.config.dictConfig(self.log_config)  #  <-------------------

やっとわかった・・・。このconfigで、3種類の root, access, error のlogging instances を定義してたんだ。

uvicorn は handlers=default なので、 stderr にいく。
uvicorn.error はhandler指定しないと root と同じ = stderr じゃないかな
unicorn.access は access handlersで、 stdout へ。

https

LOGGING_CONFIG: dict = {
    "version": 1,
    ...
    "handlers": {
        "default": {
            "formatter": "default",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stderr",
        },
        "access": {
            "formatter": "access",
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",
        },
    },
    "loggers": {
        "uvicorn": {"handlers": ["default"], "level": "INFO"},            # <-------------------
        "uvicorn.error": {"level": "INFO"},                    # <-------------------
        "uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False},         # <-------------------
    },
}

uvicorn を使う側に戻る

ってことは、同僚が教えてくれたこれは、 uvicorn の root logger = まさかの stderr を経由した出力を使っているということだったのか。

    logger = logging.getLogger('uvicorn')    

じゃあ、 uvicorn.access を経由すれば IP とか 日時も出るんじゃない？と思ったら

main6.py

import uvicorn
import logging
import os

async def app(scope, receive, send):
    assert scope['type'] == 'http'
    await send({
        'type': 'http.response.start',
        'status': 200,
        'headers': [
            [b'content-type', b'text/plain'],
        ],
    })
    await send({
        'type': 'http.response.body',
        'body': b'Hello, world!',
    })

    logger = logging.getLogger('uvicorn.access')      # <------------------------------
    logger.info('info-test')

if __name__ == "__main__":
    uvicorn.run(f"{os.path.basename(__file__).removesuffix('.py')}:app", host="127.0.0.1", port=5000, reload=True, log_level="info")

要素が足りないらしく、コケました.

INFO:     127.0.0.1:59845 - "GET / HTTP/1.1" 200 OK
--- Logging error ---
Traceback (most recent call last):
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/logging/__init__.py", line 1079, in emit
    msg = self.format(record)
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/logging/__init__.py", line 923, in format
    return fmt.format(record)
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/logging/__init__.py", line 662, in format
    s = self.formatMessage(record)
  File "/Users/ME/repos/learn-uvicorn-logger/venv/lib/python3.9/site-packages/uvicorn/logging.py", line 99, in formatMessage
    (
ValueError: not enough values to unpack (expected 5, got 0)
Call stack:
  File "<string>", line 1, in <module>
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/spawn.py", line 116, in spawn_main
    exitcode = _main(fd, parent_sentinel)
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/spawn.py", line 129, in _main
    return self._bootstrap(parent_sentinel)
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/process.py", line 315, in _bootstrap
    self.run()
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/ME/repos/learn-uvicorn-logger/venv/lib/python3.9/site-packages/uvicorn/subprocess.py", line 76, in subprocess_started
    target(sockets=sockets)
  File "/Users/ME/repos/learn-uvicorn-logger/venv/lib/python3.9/site-packages/uvicorn/server.py", line 50, in run
    loop.run_until_complete(self.serve(sockets=sockets))
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 629, in run_until_complete
    self.run_forever()
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 596, in run_forever
    self._run_once()
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/base_events.py", line 1890, in _run_once
    handle._run()
  File "/usr/local/Cellar/python@3.9/3.9.1_1/Frameworks/Python.framework/Versions/3.9/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/Users/ME/repos/learn-uvicorn-logger/venv/lib/python3.9/site-packages/uvicorn/protocols/http/h11_impl.py", line 369, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "/Users/ME/repos/learn-uvicorn-logger/venv/lib/python3.9/site-packages/uvicorn/middleware/proxy_headers.py", line 59, in __call__
    return await self.app(scope, receive, send)
  File "/Users/ME/repos/learn-uvicorn-logger/main5.py", line 20, in app
    logger.info('info-test')
Message: 'info-test'
Arguments: ()

軽くおったけどいまいちわからなかったところで時間切れ。

log ひとつ の中身 = logging.LogRecord オブジェクト

ちなみに、logging/init.py の中で log の中にある値が定義されてるのを見つけた

logger.info('info-test') とかやると、ひとつずつこういうおｂジェクトが作られる。type は logging.LogRecord

LogRecord(**{
  'name': 'uvicorn.access', 
  'msg': 'info-test', 
  'args': (), 
  'levelname': 'INFO', 
  'levelno': 20, 
  'pathname': '/Users/ME/repos/learn-uvicorn-logger/main5.py', 
  'filename': 'main5.py', 
  'module': 'main5', 
  'exc_info': None, 
  'exc_text': None, 
  'stack_info': None, 
  'lineno': 20, 
  'funcName': 'app', 
  'created': 1624507305.7061849, 
  'msecs': 706.1848640441895, 
  'relativeCreated': 70243.20578575134, 
  'thread': 4658132416, 
  'threadName': 'MainThread', 
  'processName': 'SpawnProcess-1', 
  'process': 63612
})

この定義が logging.LogRecord の中にある。
exc_info とか stack_info とか、 threadName なんかが入ってるのか。ここらへんを自前でprintしてるバッチ、logging 使えばよかったんだなぁ・・

loggig/__init__.py

class LogRecord(object):
    """
    A LogRecord instance represents an event being logged.

    LogRecord instances are created every time something is logged. They
    contain all the information pertinent to the event being logged. The
    main information passed in is in msg and args, which are combined
    using str(msg) % args to create the message field of the record. The
    record also includes information such as when the record was created,
    the source line where the logging call was made, and any exception
    information to be logged.
    """
    def __init__(self, name, level, pathname, lineno,
        ...
        self.levelname = getLevelName(level)
        self.levelno = level
        self.pathname = pathname
        ...
            self.filename = os.path.basename(pathname)
            self.module = os.path.splitext(self.filename)[0]
        ...
        self.exc_info = exc_info
        self.exc_text = None      # used to cache the traceback text
        self.stack_info = sinfo
        self.lineno = lineno
        ...
            self.thread = threading.get_ident()
            self.threadName = threading.current_thread().name

https://docs.python.org/3/library/logging.html#logging.LogRecord

けっこうわかってきた。

python logger 完全に理解した。

FYI: ここで使ったファイルはgithubに置きました。
https://github.com/kujiy/learn-uvicorn-logger/tree/master