PythonのWebアプリケーションフレームワーク（WAF）であるaiohttpでカスタムロガーを使ってアクセスログを出力する。
TL;DR
aiohttpにはアクセスログを取得する標準の仕組みがある- 出力する内容を変更するときは
AbstractAccessLoggerを実装した独自のAccessLoggerを用意する Application.run_appメソッドの引数として独自のAccessLoggerを渡してwebサーバを起動するloggerの設定は忘れずに
from aiohttp import web
from aiohttp.abc import AbstractAccessLogger
from aiohttp.web_app import Application
class CustomAccessLogger(AbstractAccessLogger):
def log(self, request,response,time: float) -> None:
self.logger.info(f'access_log')
app: Application = web.Application()
web.run_app(app, access_log_class=CustomAccessLogger)
環境
- Python 3.8.0
- aiohttp 3.6.2
独自のアクセスログを出力したい
Pythonのwebサーバでアクセスログを出力し、ログの中へリクエストヘッダーに含まれるX-Request-IDを出力しようと考えた。
利用しているWAFのaiohttpのドキュメントをみると、アクセスログとカスタマイズの仕組みが標準でサポートされていたため試してみた。
AbstractAccessLoggerを実装した独自のAccessLoggerを用いる。
aiohttpのアクセスログの仕組みは次のページに記載されている。
- Logging — aiohttp 3.6.2 documentation
基本的にはシグネチャを満たしたlogメソッドを実装すれば良い。
from aiohttp.abc import BaseRequest, AbstractAccessLogger
from aiohttp.web_response import StreamResponse
class CustomAccessLogger(AbstractAccessLogger):
def log(self,
request: BaseRequest,
response: StreamResponse,
time: float) -> None:
self.logger.info(f'access_log: {request.remote} '
f'"{request.method} {request.path} '
f'done in {time}s: {response.status}')
この自作クラスの型名をwebサーバ起動時に渡せばこれを利用したアクセスログが出力されるようになる。
app: Application = web.Application()
web.run_app(app, access_log_class=CustomAccessLogger)
このクラスはサーバ起動時に自動的に初期化されて利用される。
self.loggerから呼び出されるloggerオブジェクトは次のように決まる、
run_appメソッドの引数にaccess_logとして渡したlogging.loggerオブジェクト- 何も渡されなかった場合は
logging.getLogger('aiohttp.access')で取得できるloggerオブジェクト
上記の例では、access_logは未指定なのでlogging.getLogger('aiohttp.access')で取得できるオブジェクトになる。
実際にログ出力される形式、ログレベルは通常のloggingパッケージのエコシステムに則る。
そのため、適切なログレベルやhandlerを設定しないと出力されない。
33000ポートで起動するwebサーバに独自アクセスログを設定するコードが以下になる。
import logging
from aiohttp import web
from aiohttp.abc import BaseRequest, AbstractAccessLogger
from aiohttp.web_app import Application
from aiohttp.web_request import Request
from aiohttp.web_response import StreamResponse
class CustomAccessLogger(AbstractAccessLogger):
def log(self,
request: BaseRequest,
response: StreamResponse,
time: float) -> None:
self.logger.info(f'access_log: {request.remote} '
f'"{request.method} {request.path} '
f'done in {time}s: {response.status}')
async def handler(request: Request) -> StreamResponse:
return web.Response(text='return\n')
access_logger = logging.getLogger('aiohttp.access')
ch = logging.StreamHandler()
access_logger.setLevel(logging.INFO)
access_logger.addHandler(ch)
app: Application = web.Application()
app.router.add_get('/', handler)
web.run_app(app, port=33000, access_log_class=CustomAccessLogger)
'aiohttp.access'として登録されているlogging.loggerにhandlerとしては標準のStreamHandlerを付与している。
また、上記の例ではinfoメソッドを呼んでいるので、logger自体のログレベルをINFO以上にセットしておかないとhandlerが呼ばれない。
Access logs are enabled by default. If the debug flag is set, and the default logger ‘aiohttp.access’ is used, access logs will be output to stderr if no handlers are attached. Furthermore, if the default logger has no log level set, the log level will be set to logging.DEBUG.
ドキュメントには上記のようにデフォルトならDEBUGレベルで出力されると書いてあったが、明示的にログレベルなどを設定しないと出力されなかった。
上記コードを起動し、別ターミナルからcurlコマンドでアクセスしたときのログ出力は以下のようになった。
$ python -u main.py
======== Running on http://0.0.0.0:33000 ========
(Press CTRL+C to quit)
access_log: 127.0.0.1 "GET / done in 0.0007638730000003591s: 200
あとは、handlerを調整して、JSON形式の出力にするなり、ファイルに出力すればよい。
おわりに
Pythonのloggingパッケージのlogger、handlerまわりのエコシステムの挙動を理解せず、ログが出力できなくてだいぶハマった。
結局公式ドキュメントを読むことで解決したので、やはり言語仕様はひととおり読まないといけないなと痛感した。
参考
- Logging HOWTO — Python 3.8.2 ドキュメント
- Logging — aiohttp 3.6.2 documentation