2020年10月30日金曜日

flask のロギング機構について調べてみた

概要

flask のロギングをいろいろと試してみました
基本は python の標準の logging を使っているようです

環境

  • macOS 10.15.7
  • Python 3.8.5
    • flask 1.1.2

準備

  • pipenv install flask

とりあえず標準のログを確認してみる

  • vim app.py
from flask import Flask

app = Flask(__name__)

@app.route('/')
def hello_world():
    return 'Hello, World!'
  • FLASK_APP=app.py pipenv run flask run
  • curl localhost:5000

これで確認すると以下のようなログが表示されるのが確認できると思います

127.0.0.1 - - [30/Oct/2020 09:17:47] "GET / HTTP/1.1" 200 -

app.logger を使う

特にフォーマットをしてせずにログ出力してみます
flask では logging モジュールを使っているのでそれに対してログレベルの調整などをします
デフォルトだと warn になっている info にしてから出力してみます

  • vim app.py
import logging
from flask import Flask

app = Flask(__name__)
logging.basicConfig(level=logging.INFO)

@app.route('/')
def hello_world():
    app.logger.info('called hello world')
    return 'Hello, World!'
  • FLASK_APP=app.py pipenv run flask run
  • curl localhost:5000
INFO:app:called hello world INFO:werkzeug:127.0.0.1 - - [30/Oct/2020 09:27:37] "GET / HTTP/1.1" 200 -

こんな感じで表示されます
前半にログレベルとパッケージ名が付与されているのが確認できます

フォーマットを変更する

次にフォーマットを変更してみます
logging.configdictConfig というメソッドがあるのでこれにログの設定を与えることで変更することができます

  • vim app.py
from logging.config import dictConfig
from flask import Flask

dictConfig({
    'version': 1,
    'formatters': {'default': {
        'format': '[%(asctime)s] %(levelname)s in %(module)s: %(message)s',
    }},
    'handlers': {'wsgi': {
        'class': 'logging.StreamHandler',
        'stream': 'ext://flask.logging.wsgi_errors_stream',
        'formatter': 'default'
    }},
    'root': {
        'level': 'INFO',
        'handlers': ['wsgi']
    }
})

app = Flask(__name__)

@app.route('/')
def hello_world():
    app.logger.info('called hello world')
    return 'Hello, World!'

formatters, handlers を使って定義します
Python の logging モジュールで使用できるハンドラの一覧はこちらが参考になります
今回使用している StreamHandler は標準出力と標準エラーに出力するためのハンドラになります
ファイルに出力したい場合は FileHandler を使います
handler 内でログのフォーマットを指定します
またログレベルも dictConfig で指定できます

これで実行すると以下のように出力されます

  • FLASK_APP=app.py pipenv run flask run
  • curl localhost:5000
[2020-10-30 09:34:08,250] INFO in app: called hello world [2020-10-30 09:34:08,251] INFO in _internal: 127.0.0.1 - - [30/Oct/2020 09:34:08] "GET / HTTP/1.1" 200 -

ちなみに flask のデフォルトハンドラはすべて標準エラーに出力しています

メールの送信

エラーロギングなどをメールで飛ばすこともできます
その場合は SMTPHandler を使います
先程は dictConfig を使って dictionary 形式でロガーを設定しましたがハンドラを生成してアプリに設定することもできます
ちなみに Gmail を使う場合は以下のように設定します

  • vim app.py
import logging
from logging.handlers import SMTPHandler
from flask import Flask

mail_handler = SMTPHandler(
    mailhost=('smtp.gmail.com', 587),
    credentials=('your-google-account@gmail.com', 'app-password'),
    fromaddr='your-google-account@gmail.com',
    toaddrs=['your-google-account@gmail.com'],
    subject='Application Error',
    secure=()
)
mail_handler.setLevel(logging.ERROR)
mail_handler.setFormatter(logging.Formatter(
    '[%(asctime)s] %(levelname)s in %(module)s: %(message)s'
))

app = Flask(__name__)
app.logger.addHandler(mail_handler)

@app.route('/')
def hello_world():
    app.logger.error('An error has occurred')
    return 'Hello, World!'

これでアクセスすると標準エラーに出力されるのと同時にメールが届くのも確認できると思います
メール送信時に若干ネットワークのラグが発生するのでレスポンスが遅くなります

  • FLASK_APP=app.py pipenv run flask run
  • curl localhost:5000
[2020-10-30 10:03:51,142] ERROR in app: An error has occurred

request の情報をログに入れる

自作でフォーマッタを用意すれば request の内容を常にログに入れることもできます
default_hander に対して設定していますが独自のハンドラに設定することもできます
また default_handler の出力を表示するために development モードで起動しましょう

  • vim app.py
import logging
from flask import has_request_context, request
from flask.logging import default_handler
from flask import Flask

app = Flask(__name__)

class RequestFormatter(logging.Formatter):
    def format(self, record):
        if has_request_context():
            record.url = request.url
            record.remote_addr = request.remote_addr
        else:
            record.url = None
            record.remote_addr = None

        return super().format(record)

formatter = RequestFormatter(
    '[%(asctime)s] %(remote_addr)s requested %(url)s '
    '%(levelname)s in %(module)s: %(message)s'
)

default_handler.setFormatter(formatter)
default_handler.setLevel(logging.INFO)

@app.route('/')
def hello_world():
    app.logger.info('called hello world')
    return 'Hello, World!'

確認すると以下のようなログが追加で表示されるのが確認できると思います

  • FLASK_ENV=development FLASK_APP=app.py pipenv run flask run
  • curl localhost:5000
[2020-10-30 11:09:58,170] 127.0.0.1 requested http://localhost:5000/ INFO in app: called hello world

デフォルトの werkzeug ロガーのフォーマットを変更する

デフォルトで表示されているリクエストログは werkzeug というモジュールのロガーになります
これにハンドラを追加すればフォーマットを変更できます
例えば先程の RequestFormatter にする場合は以下のようにします

import logging
from flask import has_request_context, request
from flask.logging import default_handler
from flask import Flask

app = Flask(__name__)

class RequestFormatter(logging.Formatter):
    def format(self, record):
        if has_request_context():
            record.url = request.url
            record.remote_addr = request.remote_addr
        else:
            record.url = None
            record.remote_addr = None

        return super().format(record)

formatter = RequestFormatter(
    '[%(asctime)s] %(remote_addr)s requested %(url)s '
    '%(levelname)s in %(module)s: %(message)s'
)

default_handler.setFormatter(formatter)
default_handler.setLevel(logging.INFO)

werkzeug_logger = logging.getLogger('werkzeug')
werkzeug_logger.addHandler(default_handler)

@app.route('/')
def hello_world():
    app.logger.info('called hello world')
    return 'Hello, World!'
  • FLASK_ENV=development FLASK_APP=app.py pipenv run flask run
  • curl localhost:5000
[2020-10-30 11:16:14,753] 127.0.0.1 requested http://localhost:5000/ INFO in app: called hello world [2020-10-30 11:16:14,754] None requested None INFO in _internal: 127.0.0.1 - - [30/Oct/2020 11:16:14] "GET / HTTP/1.1" 200 -

最後に

flask のロギング機構について調べてみました
基本はハンドラを作成してそのハンドラに対してログレベルやフォーマットを設定し作成したハンドラをアプリのロガーに設定するという流れになります
ハンドラは自分で作成もできますし Python にいくつか標準で準備されているハンドラがあるので自分のやりたいことにあったハンドラを使えば OK です

参考サイト

0 件のコメント:

コメントを投稿