PythonのデコレータでAOPっぽいことをしました。

この記事は ハンズラボ Advent Calendar 2017 9日目の記事です。

おはようございます。@naokiurです。
僭越ながら、登場2回目です。宜しくお願い致します。

今回は(今回も？)、完全に個人の考えを執筆させて頂きます…！

1回目のときにも書かせて頂きましたが、今のチームではDjangoとVueJSで開発をしております。
転職前から個人的に勉強をしていましたが、Pythonを業務で使用するのは初めてで、
個人的に新しいものに触れることができているという意味で、刺激的な毎日を送ることができており、非常にありがたいです。

元々前職では、JavaでWebアプリケーション開発をしたりしていました。
初めてのWebアプリケーション開発は、2012年くらい？で、Seasar2を使っておりました。
当時の経験や、先輩方に教えて頂いたことが、自分の原点であると言っても過言ではありません。

そのときに、AOPも教えて頂きました。
非常に便利・分かりやすいという印象だったので、Pythonでも導入したい…！
と思ったのですが…AOPライブラリを、あまり見つけることができませんでした…。

なぜだ…あんなに便利なものなのに…！

と思っていましたが、ライブラリ、という切り口で探していたのがよくなかったようです。
Pythonにはデコレータというものがあり、関数の前後で処理を書くことができる、とのこと。

だから、AOPライブラリがあまりないのか、という理解をしております。
(違っていたら、ご指摘頂けると幸いです…)

ということで、今回は、Pythonのデコレータを使って、
ログ出力をAOPっぽい感じで実装したいと思います。
…っぽくなってたらいいなあ…と思います。

AOPとは

アスペクト指向プログラミング(Aspect Oriented Programming)のこと。

Wikipediaによると、

アスペクト指向プログラミング（アスペクトしこうプログラミング、Aspect Oriented Programming、AOP）は、
オブジェクト指向ではうまく分離できない特徴（クラス間を横断 (cross-cutting) するような機能）を「アスペクト」とみなし、
アスペクト記述言語をもちいて分離して記述することでプログラムに柔軟性をもたせようとする試み。
アスペクトの例としては、データ転送帯域の制限や例外の処理などがある。Java にアスペクト指向的要素を追加したAspectJ が実験的に実装されている。

とのことです。
ログ出力や認証などを「横断的な関心事」と呼び、
それらを、複数のクラス・メソッドに何度も書かなくてよくなる、
というすごいものだ、という認識をしております。

Seasar2ではInterceptorと呼んでいたと記憶しております。
懐かしい。

デコレータとは

Python documentによると、

別の関数を返す関数で、通常、 @wrapper 構文で関数変換として適用されます。

とのことです。
@wrapper構文で記載することにより、実行可能な文をラップしてくれるというものだそうです、
すごい！

やりたいこと

いわゆるトレースログを実装したいと思います。
よくある、このメソッドの開始時と終了時に、出力するログです。

デコレータ実装前

views.py

class UserViewSet(viewsets.ModelViewSet):
    queryset = User.objects.all().order_by('-date_joined')
    serializer_class = UserSerializer
    log = getLogger(LOGGER_NAME)

    def list(self, request):
        self.log.info("ユーザ取得機能開始")

        # 何かの処理
        time.sleep(1)

        print("users, execute something.")

        # 何かの処理
        time.sleep(1)

        self.log.info("ユーザ取得機能終了")
        return Response()


class GroupViewSet(viewsets.ModelViewSet):
    queryset = Group.objects.all()
    serializer_class = GroupSerializer
    log = getLogger(LOGGER_NAME)

    def list(self, request):
        self.log.info("グループ取得機能開始")

        # 何かの処理
        time.sleep(1)

        print("groups, execute something.")

        # 何かの処理
        time.sleep(1)

        self.log.info("グループ取得機能終了")
        return Response()

メソッドの始まりと終わりに、log.info()を呼ぶ形です。
出力結果は以下のようになり、やりたいことは叶えられていますが、例では2つのクラス、1つずつのメソッドしかないため、そこまで手間ではないですが、
実際のプロジェクトでは、はるかに多いクラス、メソッドを実装する必要があることが大半であるはず、
ささやかな事ですが、積み重ねにより、大変になってしまうと考えられます。

デコレータ実装後

logger.py

def logger(func):
    def inner(*args, **kwargs):
        log = getLogger(LOGGER_NAME)

        # args[0]：実行されたクラス
        # args[1]：requestオブジェクト
        log.info(str(args[0].__class__) + "開始")

        result = func(*args, **kwargs)

        log.info(str(args[0].__class__) + "終了")

        return result

    return inner

views.py

class UserViewSet(viewsets.ModelViewSet):
    queryset = User.objects.all().order_by('-date_joined')
    serializer_class = UserSerializer

    @logger
    def list(self, request):
        # 何かの処理
        time.sleep(1)

        print("users, execute something.")

        # 何かの処理
        time.sleep(1)

        return Response()


class GroupViewSet(viewsets.ModelViewSet):
    queryset = Group.objects.all()
    serializer_class = GroupSerializer

    @logger
    def list(self, request):
        # 何かの処理
        time.sleep(1)

        print("groups, execute something.")

        # 何かの処理
        time.sleep(1)

        return Response()

デコレータにより、「@logger」と書くだけで良くなり、
views.pyから開始/終了のログ出力部分を分離することができました！

出力結果は以下のようになりました。
どのクラスが実行されたかを取得するために、
デコレータ側でargs[0]に格納されているクラスから、
__class__を取得しました。

これにより、特定できると思うのですが、
(privateなフィールド__class__にアクセスしてしまっているし)
より自由なログ出力のために、「引数付きデコレータ」を作成致しました。

引数付きデコレータ実装後

logger.py

def logger(func_name):
    def __decorator(func):
        def inner(*args, **kwargs):
            log = getLogger(LOGGER_NAME)

            log.info(func_name + "開始")

            result = func(*args, **kwargs)

            log.info(func_name + "終了")

            return result

        return inner

    return __decorator

views.py

class UserViewSet(viewsets.ModelViewSet):
    queryset = User.objects.all().order_by('-date_joined')
    serializer_class = UserSerializer

    @logger(func_name="ユーザ取得機能")
    def list(self, request):
        # 何かの処理
        time.sleep(1)    

        print("users, execute something.")

        # 何かの処理
        time.sleep(1)

        return Response()


class GroupViewSet(viewsets.ModelViewSet):
    queryset = Group.objects.all()
    serializer_class = GroupSerializer

    @logger(func_name="グループ取得機能")
    def list(self, request):
        # 何かの処理
        time.sleep(1)

        print("groups, execute something.")

        # 何かの処理
        time.sleep(1)

        return Response()

出力結果は以下のようになり、記述量を最小限にしつつ、
元々実施していた日本語でのログ出力もできるようになりました！

今後

今回はデコレータを使用しましたが、書いたあといろいろ調べたところ、
Custom Middleware、というのの方が、DjangoでAOP的なことをやるにはふさわしそう？ です…。
なので、そちらも試したいな、と思います。

ハンズラボ Advent Calendar 2017 10日目の明日は、
Qiitaアドベントカレンダーの登録開始時に、速攻でハンズラボのカレンダーを作成して下さった、@daikiojmさんです！

参考にさせて頂きました。