そうだ、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://github.com/encode/uvicorn/blob/b5af1049e63c059dc750a450c807b9768f91e906/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}, # <-------------------
},
}
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