Flask(v1.0.2)のログ機能に関するメモ

はじめに

Pythonのマイクロフレームワークである Flask のログ機能について調べた時のメモです。バージョンは以下のようになっています。

	バージョン
Flask	1.0.2
Python	3.7.0

まず、デフォルトのログに関する設定について整理し、その上で何かしら設定する際に気をつけたほうがいいことを書いています。

Flaskは、Python標準のloggingモジュールを使用しています。loggingそのものについては一切触れていないので、Logging HOWTO — Python 3.6.5 ドキュメント などを参照ください。

flask.app Logger

Flaskのアプリケーションオブジェクトは logging.getLogger('flask.app') で得られるロガーを保持しています。保持しているロガーには Flask.logger でアクセスできます。ログ出力は、debug(), info(), warning(), error(), exception(), critical() を目的に応じて使い分けます。

from flask import Flask

app = Flask(__name__)
app.logger.debug('debug')
app.logger.info('info')
app.logger.warning('message')
app.logger.error('error')
app.logger.critical('critical')

flask run などでアプリケーションを実行すると、ログが出力されるはずです。標準エラー出力にログを出すだけならこれでおしまいです。

[2018-09-21 15:25:08,857] WARNING in app: message
[2018-09-21 15:25:08,857] ERROR in app: error
[2018-09-21 15:25:08,857] CRITICAL in app: critical

Logger のログレベルとハンドラ(出力先とログフォーマット)の設定は、flask.app Loggerを使うタイミングで自動的に設定されます。以下にそれぞれどのように設定されているかを書いておきます。

ログレベルについて

上記例では、debug() と info() のログが出力されていません。これは、ログレベルが WARNING になっているためです。ログレベルは、Flaskの実行環境に応じて変化します。

実行環境	ログレベル
production	WARNING
development	DEBUG

デフォルトでは production のため、ログレベルは WARNING に設定されます。development だと DEBUG に設定されるので、以下のようにすべてのレベルのログが出力されます。FLASK_ENV=development を環境変数にセットして試してみると良いでしょう。

[2018-09-21 15:24:42,183] DEBUG in app: debug
[2018-09-21 15:24:42,184] INFO in app: info
[2018-09-21 15:24:42,184] WARNING in app: message
[2018-09-21 15:24:42,184] ERROR in app: error
[2018-09-21 15:24:42,184] CRITICAL in app: critical

ハンドラについて

ログの出力先とログフォーマットが設定されたハンドラは、default_handler として定義されています。また、 default_handlerは、以下のような設定になっています。

設定項目	値
ログレベル	NOTSET
出力先	標準エラー出力(この場合はターミナル)
フォーマット	[%(asctime)s] %(levelname)s in %(module)s: %(message)s

app.logger を実行した時点で有効なハンドラが設定されていない場合、flask.app Logger に自動で追加されるようになっています。default_handler はインポートできます。

from python.logging import deafult_handler

公式ドキュメント に書いてあるように、あとからハンドラを削除することもできます。逆に、追加したり、別のところで default_handler を使い回すこともできます。

werkzeug Logger

なんらかのルーティングを定義してアプリケーションにリクエストを送ると、ログが出力されます。

@app.route('/')
def index():
    return 'hello'

127.0.0.1 - - [21/Sep/2018 10:35:50] "GET / HTTP/1.1" 200 -

このログを出力しているのは、werkzeug というライブラリが logging.getLogger('werkzeug') で取得しているロガーです。flask.app Logger ではありません。werkzeug はFlask内部で使われているライブラリです。werkzeug Logger も未設定の場合に、同様にデフォルト値が設定されるようになっています。

設定項目	値
ロガーのログレベル	INFO
ハンドラーのログレベル	NOTSET
出力先	標準エラー出力
フォーマット	指定なし

見るからにフォーマットされたような文字列ですが、単純にテキストをつなぎ合わせているだけだったりします(参考)。上記設定は、RootとなるLoggerにハンドラが設定されていない、もしくは、このロガーにログレベルが設定されていない場合に適用されます。

ログ設定時に気をつけること

冒頭で述べたように、いずれのロガーもPython標準のloggingを使っています。したがって、ロガーにハンドラを追加したり削除すればログの出力先を変更できます。その具体的な方法はここでは述べません。Pythonのログの設定については、以下の記事が参考になります。

realpython.com

ログ設定については上記記事にお任せするとして、ここではFlaskで諸々設定する際に気をつけることを書いておきます。

werkzeugのログフォーマット

先述したように、werkzeug が出力するログはフォーマットされたものではありません。したがって、werkzeug Logger に default_handler を設定すると、微妙なログになってしまいます。

from flask import Flask
from flask.logging import default_handler
import logging

app = Flask(__name__)
werkzeug_logger = logging.getLogger('werkzeug')
werkzeug_logger.addHandler(default_handler)
werkzeug_logger.setLevel(app.logger.getEffectiveLevel())

[2018-09-21 15:26:42,184] INFO in _internal: 127.0.0.1 - - [23/Sep/2018 01:34:13] "GET / HTTP/1.1" 200 -

werkzeug の _internal.py でログが吐かれているのでモジュール名が _internal になっています。また、日付が異なるフォーマットで2つ書かれていたりします。werkzeug のログフォーマットを修正するのは少し手間がかかりそうです。

IPアドレス や リクエストURL は公式ドキュメントに書いてある方法でログに含められます。その場合、werkzeug が出力するログは不要になります。次に示す方法でロガーを無効化すれば、ログが出力されなくなります。

ロガーを無効化する

ロガーに disabled=True を指定することで、ログが出力されなくなります。

import logging
logging.getLogger('werkzeug').disabled = True

リクエストログを自動で出力させる

werkzeug を無効化すると、リクエストの度にログが出力されなくなります。リクエストの度に明示的に関数を実行しなければいけないのは少し手間です。before_request もしくは after_request を使うことで、自動でログを出力できるようになります。

@app.before_request
def logging_request():
    app.logger.info("before request")

たとえば、上記のように書くことでアプリケーションがリクエストを受け取るたびにログが出力されるようになります。before_request なので、URLに対応する関数が実行される前にログが出力されます。after_request の場合、関数実行後に処理されます。

Root Logger との関係

Root Loggerにハンドラがある場合も、default_handlerは設定されません。そのため、app.logger にアクセスする前にloggingモジュールでログを出力してしまうと、default_handlerは追加されなくなります。ログ出力のタイミングで標準モジュールのデフォルトハンドラが RootLoggerに対して追加されてしまうためです。その結果、2行目のフォーマットが %(levelname)s:%(name)s:%(message)s になっていることがわかると思います。

from flask import Flask
import logging

app = Flask(__name__)
logging.warning("warning by standard module")
app.logger.warning("warning by flask.app logger")

WARNING:root:warning by standard module
WARNING:flask.app:warning by flask.app logger

werkzeug のロガーも同様にデフォルトのハンドラが登録されません。いずれもデファルトでは propagate=True であるため、ロギングメッセージは祖先のロガーにも渡されます。なので、Root Loggerにハンドラが設定されていれば、Root Logger によってログが出力されます。

厳密な default_handler の追加条件

default_handler が flask.app Logger に設定される条件は、厳密には「ハンドラが設定されていない場合」ではありません。祖先のロガーまで辿り、その中に flask.app Logger のログレベル以下のハンドラがない場合に追加されます(参考)。デバッグモードで実行した場合、flask.app Logger のログレベルは DEBUG になります。ログレベルが INFO 以上のハンドラーしかない場合、default_handler が追加されてしまいます。諸々設定したあと2重にログが表示されたりした場合、この振る舞いが影響している可能性があります。