djangoのクラスベースドビューの例外処理について

結論

LOGGINGを適切に設定しろ

やりたかった事

def my_logger_decorator(func):
    def wrapper(*args, **kwargs):
        try:
            print('【API start】function:', func)
            result = func(*args, **kwargs)
            print('【API end】status_code:', result.status_code)
            return result
        except Exception as e:
            print('!!------error occured------!!')
            traceback.print_exc()
            raise e
    return wrapper

上記decoratorを全てのクラスベースドビューに適用して、独自なログ管理とか例外処理をやりたかった。
以下みたいなイメージ

import my_logger_decorator
# dispatchに対してデコレーターをあてるとクラスベースドビューの関数にデコレーターが当てられる
@method_decorator(my_logger_decorator, name='dispatch')
class myView(TemplateView):
    template_name = 'myapp/superultrahypermiracle.html'

    def get_context_data(self, objectList=None, **kwargs):
        context = super().get_context_data(**kwargs)
        # 例えば、下記の検索条件でカラム名タイポや.get()なのに複数存在するなどの例外が起きたらキャッチしたい
        example = MyModel.objects.filter(columnA=True).get()
        context.update(
            example=example
        )

        return context

こうしておけば例外全部キャッチ出来るしAPIの開始と終了も取れるしいい感じかなーと思っていた

現実

出来なかった。
正確には、0除算みたいな例外は取れるんだけど、テンプレートのレンダリング時のエラー等が取れない。何が起こるかというと、例えば、カラム名にタイポがあり、存在しないカラムに対して条件を設定していた場合は下のようになる。

【API start】function: functools.partial(<bound method myView.dispatch of <myapp.views.myView object at 0x015FAFB0>>)
【API end】status_code: 200
[09/Apr/2019 21:05:05] "GET / HTTP/1.1" 500 193

デコレーター時点では例外が発生せず、status_codeにも200(正常終了)が入っているのに、djangoの最終的なアウトプットは500になっている。この時djangoが生成するログやDEBUG時に見えるエラーページには明確に

Cannot resolve keyword 'columnB' into field. Choices are: columnA, id

と出てくる。つまりdjangoは例外を正確にキャッチしている。なにこれ？

原因

djangoのquerysetAPIが遅延評価を行う事が原因。
"処理の終わり"のタイミングがフレームワークの仕組みに埋もれていて、この後もモリモリ処理がある事も原因。

参考：
QuerySet API リファレンス
※古いバージョンの公式ドキュメントですが日本語なので分かりやすい。今回話題にしたいのはタイミングの話のみで、バージョン間に差分がなさそうなのでこっちを引用

Djangoのクエリセット評価タイミング実験
※みんなだいすきqiitaにも先人の良いのがあった。ありがたい。

つまり、今回例にしたソースではget_context_data中にfilterの条件ミスを書いたが、この例外はcontextが評価されるまで発現しないため、今回のデコレーターの範囲内では例外化しないらしい。ホゲー

この例外がどこで発現するかというと、django.core.handlers.base.pyの153行目あたりで発現していた。

            try:
                response = response.render() # ここで評価されて例外が発生する
            except Exception as e:
                response = self.process_exception_by_middleware(e, request) # middlewareで例外が起きたよーという結果を上に返す

middlewareで例外だよーになるのは若干腑に落ちてないんですがSQL発行に関連する例外だからなんですかね？settings.pyのMIDDLEWAREに記載はしてないけどなー。

その後なんやかんやあり、responseの中が例外オブジェクト(?)の場合はdjango.core.handlers.exception.py中の18行目のデコレータに処理がいく

def convert_exception_to_response(get_response):
    """
    Wrap the given get_response callable in exception-to-response conversion.

    All exceptions will be converted. All known 4xx exceptions (Http404,
    PermissionDenied, MultiPartParserError, SuspiciousOperation) will be
    converted to the appropriate response, and all other exceptions will be
    converted to 500 responses.

    This decorator is automatically applied to all middleware to ensure that
    no middleware leaks an exception and that the next middleware in the stack
    can rely on getting a response instead of an exception.
    """
    @wraps(get_response)
    def inner(request):
        try:
            response = get_response(request)
        except Exception as exc:
            response = response_for_exception(request, exc)
        return response
    return inner

docstringを読む限り、このデコレータは勝手に全てのget_responseについているらしい。ホゲー
djangoのResponseはtemplateView等の仕組みに則っているとget_responseを用いて作成されるので、全部の応答に噛むように出来ている。

get_response中で例外が発生した場合、response_for_exception()に処理が渡る。この時第二引数に例外の内容を渡している。
response_for_exception()の中身を一部抜粋すると

    elif isinstance(exc, PermissionDenied):
        response = get_exception_response(request, get_resolver(get_urlconf()), 403, exc)
        log_response(
            'Forbidden (Permission denied): %s', request.path,
            response=response,
            request=request,
            exc_info=sys.exc_info(),
        )

こんな感じで、引数で渡された例外の種類に応じて処理を分岐しましょーねをやっている。やる内容の基本は2つ。
1つ目はlog_response()で、標準出力に何が起きたかを出力しているだけ。(これがあるので標準出力が賑やかになる)
2つ目は後続に向けてget_exception_responseを生成してresponseとしている。次はこれを見たかったのだが時間切れ……。多分だけど、djangoをDEBUG=Trueで動かしてる時に出るエラー画面を生成してると思われる……多分(自信ない)

結論ツー

djangoという枠組みに適当に乗っかっていると、自分の認識の外で行われている処理が沢山ある。ので、適当に乗っかりたいならdjangoの用意した手段に沿うのが一番楽。

というわけでsetting.pyにLOGGINGの設定を書きましょう。
参考：
[Python] Django ログ出力のまとめ

例外処理についてはhander500をオーバーライドしましょう。
参考：
django: 例外(exception)をログに残すようにする

ちゃんと書けばちゃんと動くらしい。今書いてるので気が向いたらまとめます。おわり

TonamiLog

ゆるキャン△とスノーボードとオタク

djangoのクラスベースドビューでログとか例外とかをいい感じにしたかった

djangoのクラスベースドビューの例外処理について

結論

やりたかった事

現実

原因

結論ツー