Azure WebAppsでFlaskのスタックトレースを見る #Python

はじめに

AzureのWebAppsにFlaskアプリケーションをデプロイしたところ、解決するのに1週間かかりました。
Python3.6を境にjson.loads()の動きが変わっていたことで1週間ハマりました ToT
WebAppsからエラーのスタックトレースが見られなかったのが1週間かかった原因です。
次回のエラーの解決時間を短縮するために、WebAppsでスタックトレースを見る方法を調べてみました。

TL;DR

WebAppsでFlaskアプリケーションのエラーのスタックトレースを表示するにはFlaskのloggerを使えばよい。
WebAppsで診断ログの設定も試したが、スタックトレースは見られなかった。

動作環境

ローカル開発環境
- Python 3.6.5
- Flask==0.12.2
WebApps
- Python 3.4.1
- Flask==0.12.2

何が問題だったか

Flaskアプリケーションの実行時にエラーとなった場合、500 Internal Server Error以上の情報が得られない。

Flaskの検証用サーバをローカルPCで実行しているとき、実行時に落ちるとスタックトレースが表示されます。
しかしWebAppsではスタックトレースが見られませんでした。(後述しますが、診断ログの設定をしても見られませんでした)

解決法

Flaskに用意されているlogger(app.logger)を設定する。¹²

main.py

import json
import logging
from logging.handlers import RotatingFileHandler
import os

from flask import Flask
from flask import jsonify
from flask import request


app = Flask(__name__)
log_file_path = os.environ['MY_FLASK_LOG']
handler = RotatingFileHandler(log_file_path, maxBytes=10000, backupCount=1)
handler.setLevel(logging.INFO)
formatter = logging.Formatter(
    "[%(asctime)s] {%(pathname)s:%(lineno)d} %(levelname)s - %(message)s")
handler.setFormatter(formatter)
app.logger.addHandler(handler)

@app.route('/')
def hello_world():
    return 'Hello, World!'

@app.route('/response', methods=['POST'])
def print_data():
    parsed = json.loads(request.data)
    # TODO: parsedをログに出力
    response = jsonify({'foo': 'bar'})
    response.status_code = 200
    return response


if __name__ == '__main__':
    app.run()

/responseにPOSTするとエラーとなって処理が落ちます。(Python3.4系でjson.loads()にbytes型が渡るため)
スタックトレースはD:\home\LogFiles\MyFlaskLog\app.logに記録されます³。(書き込まれるのに5分程度のラグがあるようです)
このファイルはKuduからダウンロードして確認できます。(この記事の冒頭のスクリーンショットはダウンロードしたapp.logです)

KuduはWebAppsのURLにscmを挿入すればアクセスできます。詳しくは以下のリンクを参照ください。
Azure Web Appsの中を「コンソール」や「シェル」でのぞいてみる (3/3)

WebAppsで診断ログの設定をするとどうなるか

解決策ではなかったのですが、WebAppsの診断ログについて分かったことをまとめておきます。
Azure App Service の Web アプリの診断ログの有効化

以下のように診断ログを設定しましたが、500エラー以上の情報は入手できませんでした。

アプリケーションログは詳細なエラーログと同じ情報が見られた。(詳細なエラーログは/LogFiles/DetailedErrors/⁴以下で確認できる)

Webサーバーログはステータスコードいくつを返したかという情報。(/LogFiles/http/RawLogsに配置される)

失敗した要求トレース(/LogFiles/W3SVC#########/)はたしかに詳細だが、見ても何が問題なのかよくわからなかった。
アプリケーションログ(/LogFiles/Application/)はフォルダが存在しないため、よくわからない。(設定ミスなのだろうか？)

終わりに

WebAppsでスタックトレースを見るにはAzure側ではなくデプロイするFlaskアプリケーションで設定する必要があることがわかりました。
1週間ハマったことに対してはPythonのバージョンを揃えることで再発防止を図りますが、
スタックトレースが見られるようになったので、今後もWebAppsに触っていくのが楽しみになりました。

RotatingFileHandlerはマルチスレッドのロギングに向かないとコメントいただいています。loggingはこれから勉強していきます。

今回のソースコードは以下にあります。(masterブランチではない点にご注意ください)
https://github.com/ftnext/python-docs-hello-world/tree/feature/show_errorlog

脚注

次のgistコメントを参考にしました。https://gist.github.com/ibeex/3257877#gistcomment-946336 ↩
開発環境とWebAppsとでOSが異なるので、ログファイルのパスは環境変数に設定することにしました。診断ログを有効化すると作られるLogFilesフォルダ以下に配置しています。 ↩
当初はFlaskアプリケーションと同じフォルダにログファイルを作成していました(D:\home\site\wwwroot\app.log)。適切な場所ではないと思われるというコメントをいただいたので、診断ログのフォルダに変更しています。ただしTechBlogにはwfastcgiのログをアプリケーションと同じフォルダに置いているエントリがあり(https://blogs.msdn.microsoft.com/azureossds/2015/07/14/troubleshoot-logging-python-application-errors-on-azure-webapi-apps/ )、やや混乱しています。どのフォルダに置くべきかご存じの方はコメントいただけると助かります。 ↩
フォルダ配置については「解決法」セクションのKuduのコンソールのスクリーンショットも合わせて参照ください。 ↩