PlayFramework2.6(Java)での全リクエスト/レスポンスのログ出力

こんにちは。
増田です。

以前PlayFrameworkで全リクエスト/レスポンスを取る必要に駆られたので、
その方法をあれこれ考えたり調べりした結果をここに記しておきます。

準備

何はともあれその準備から

プロジェクト作成

ターミナルで

> sbt new playframework/play-java-seed.g8

あと僕はEclipseで開発しているので、それ用の設定としてちょこっと。
project/plugins.sbtに1行追記

addSbtPlugin("com.typesafe.sbteclipse" % "sbteclipse-plugin" % "5.2.4")

そして

> sbt eclipse

これでEclipseのための準備は整いました。

API作成

APIがないとリクエスト飛ばして試せないので仕方なく作ります。
routesに

GET     /api/get                    controllers.ApiController.get
GET     /api/getWithArg/:arg        controllers.ApiController.getWithArg(arg: String)
+nocsrf
POST    /api/post                   controllers.ApiController.post

GETリクエストに、POSTリクエスト。
で、Actionとして

public class ApiController extends Controller{

    public Result get() {
        Request req = request();
        String res = "This is a response from get.";
        return ok(Json.toJson(res));
    }

    public Result getWithParam(String param) {
        Request req = request();
        String res = "This is a response from get(String).";
            return ok(Json.toJson(res));
    }

    public Result post() {
        Request req = request();
        String res = "This is a response from get(String).";
        return ok(Json.toJson(res));
    }

}

を設定。
適当にsessionも入っていたりする設定です。

本題

そんな状況で、可能な限り完璧な状態の全リクエスト/レスポンスの内容をログに出力する、
というのがやりたいことです。
「完璧な」というのはリクエストメソッド、リクエストURL、リクエスト/レスポンスbody、セッション、など。

リクエストはcurl使うなりChromeの拡張使うなりフロント作りなりして適当に。
僕はChromeの拡張を使いました。便利！

気合いでLoggerを挟む

こんな感じです。

public Result get() {
    Request req = request();
    Logger.debug("Request(Controller) : " + req.toString());
    Logger.debug("Session(Controller) : " + session("SESSION"));

    String res = "This is a response from get().";
    Logger.debug("Response(Controller) : " + res + "\n");
    return ok(Json.toJson(res));
}

public Result getWithParam(String param) {
    Request req = request();
    Logger.debug("Request(Controller) : " + req.toString());
    Logger.debug("Session(Controller) : " + session("SESSION"));

    String res = "This is a response from get(String).";
    Logger.debug("Response(Controller) : " + res + "\n");
    return ok(Json.toJson(res));
}

public Result post() {
    Request req = request();
    Logger.debug("Request(Controller) : " + req.toString() + " ; " + req.body().asJson());
    Logger.debug("Session(Controller) : " + session("SESSION"));

    String res = "This is a response from post().";
    Logger.debug("Response(Controller) : " + res + "\n");
    return ok(Json.toJson(res));
}

すると、まぁ普通にログを取れて、

[debug] application - Request(Controller) : GET /api/get
[debug] application - Session(Controller) : session_content
[debug] application - Response(Controller) : This is a response from get().

[debug] application - Request(Controller) : GET /api/getWithArg/arguments
[debug] application - Session(Controller) : session_content
[debug] application - Response(Controller) : This is a response from get(arg).

[debug] application - Request(Controller) : POST /api/post ; {"body":"body_content"}
[debug] application - Session(Controller) : session_content
[debug] application - Response(Controller) : This is a response from post().

ただ、これは気合いでしかありません。

今回の例ではAPIが3つしかないから全然問題ありませんけど、
このAPIが10、20、30...と増えてきたら、それはもう大変面倒なことに...。
でも精々数十くらいなら書いてしまっても大丈夫といえば大丈夫な気がします。

ちなみに、sessionは

session("SESSION", "session_content");

みたいな感じで設定されているものとしています。

これはしんどいので、別の方法を考えます。

Filterを利用する

Filterが何かは僕もよく分からないので割愛します。
他の方々のありがたい記事がありますのでそちらを参考にしていただいて。
とりあえずリクエストやレスポンスをフィルターしているものなのだろうという理解です。
Filterを使ってリクエスト/レスポンスをログに出力してみます。
まず、app下にfiltersディレクトリを作って、その下にMyFilterクラスを適当に作ります。
こんな感じです。

public class MyFilter extends Filter{
@Inject
    public MyFilter(Materializer mat) {
        super(mat);
    }

    @Override
    public CompletionStage<Result> apply(
            Function<Http.RequestHeader, CompletionStage<Result>> nextFilter,
            Http.RequestHeader requestHeader) {
        long startTime = System.currentTimeMillis();
        return nextFilter.apply(requestHeader).thenApply(result -> {
            long endTime = System.currentTimeMillis();
            long requestTime = endTime - startTime;

            Logger.debug("Request(Filter) : " + requestHeader.method() + " " + requestHeader.uri());
            Logger.debug("Response(Filter) : " + result.body() + "\n");

            return result.withHeader("Request-Time", "" + requestTime);
        });
    }
}

あと、このフィルターを有効にするためにapplication.confに1行

play.filters.enabled += filters.MyFilter

を追記します。

すると、こんな感じに。

[debug] application - Request(Filter) : POST /api/post
[debug] application - Response(Filter) : play.http.HttpEntity$Strict@273ad9ad

面倒になったのでPOSTリクエストだけで試しました。
この方法だとリクエストボディもセッションもレスポンスボディの内容も取れないので、残念。
そもそも用途が明らかに違うのでそんなこと言っても仕方ないのですが。

ただ、これなら一々全てのAPIに何かを加えたりという気合いは必要ありません。

Authenticatorを利用する

Authenticatorが何かは僕もよく分からないので割愛します。
他の方々のありがたい記事がありますのでそちらを参考にしていただいて。こちらなど。
なんだかリクエストをインターセプトしているみたいなのでそれを利用しようという魂胆です。
適当にappの下にauthenticatorsというディレクトリを作って、その下にMyAuthenticatorというクラスを作りました。

public class MyAuthenticator extends Authenticator {

    @Override
    public String getUsername(Context ctx) {
        String session = ctx.session().get("SESSION");
        Logger.debug("Request(Authenticator) : " + ctx.request() + " ; " + ctx.request().body().asJson());
        Logger.debug("Session(Authenticator) : " + session);
        Logger.debug("Response(Authenticator) : " + ctx.response());
        if (session != null) {
            return "ok";
        } else {
            return null;
        }
    }

    @Override
    public Result onUnauthorized(Context ctx) {
        String session = ctx.session().get("SESSION");
        if (StringUtils.isEmpty(session)) {
            return unauthorized();
        } else {
            return forbidden();
        }
    }

}

というようなことを書いて、あとはcontrollersの各Actionにアノテーションを

@Authenticated(MyAuthenticator.class)

というように付与すれば、そのアノテーションをつけられたActionへのリクエストは、
設定したAuthenticatorを通るようになります。
名前の通り本来は認可のための機構でしょうけど、細かいことは気にしません。
Authenticatorを通るので、だったらそこでログ取れば良いのでは、という安易な考えです。
でも、これだとリクエストは取れるものの、レスポンスが取れません。
こんな感じです。

[debug] application - Request(Authenticator) : POST /api/post ; {"body":"body_content"}
[debug] application - Session(Authenticator) : session_content
[debug] application - Response(Authenticator) : play.mvc.Http$Response@52f8ea91

レスポンスボディ...。

ちなみに、このアノテーションはAction毎にではなくクラス単位で付けることができます。

ActionCreatorを利用する

ActionCreatorが(割愛
他の方々の(割愛
適当にappの下にinterceptorsというディレクトリを作って、その下にMyActionCreatorというクラスを作りました。

public class MyActionCreator implements play.http.ActionCreator {
    @Override
    public Action createAction(Http.Request request, Method actionMethod) {
        return new Action.Simple() {
            @Override
            public CompletionStage<Result> call(Http.Context ctx) {

                Logger.debug("Request(ActionCreator) : " + request.method() + " " + request.uri() + " ; " + request.body().asJson());
                Logger.debug("Session(ActionCreator) :"+ctx.session().get("SESSION"));

                CompletionStage<Result> stage = delegate.call(ctx);
                stage.thenAccept(result ->{
                    Logger.debug("Request(ActionCreator) : " + result.body());
                });
                return stage;
            }
        };
    }

}

そしてFilterと同じように、これを有効にするためにapplication.confに1行

play.http.actionCreator = interceptors.MyActionCreator

を追記します。

これで出力させるとこんな感じです。

[debug] application - Request(ActionCreator) : POST /api/post ; {"body":"body_content"}
[debug] application - Session(ActionCreator) :session_content
[debug] application - Request(ActionCreator) : play.http.HttpEntity$Strict@21b69a9

どうしてもレスポンスボディだけ取れませんでした。
残念。

まとめ

というわけで自分にはこれが限界でした。
とりあえずActionCreatorを使っておけばたくさん取れるという認識です。
そして切り替えが簡単。
ちゃんと取れる上に何かもっときれいな方法はあるのだろうか...。

ちなみに、以上のものを全て繋げるとこんな感じで出力されます。

[debug] application - Request(Authenticator) : POST /api/post ; {"body":"body_content"}
[debug] application - Session(Authenticator) : session_content
[debug] application - Response(Authenticator) : play.mvc.Http$Response@32532696
  
[debug] application - Request(ActionCreator) : POST /api/post ; {"body":"body_content"}
[debug] application - Session(ActionCreator) :session_content
[debug] application - Request(Controller) : POST /api/post ; {"body":"body_content"}
[debug] application - Session(Controller) : session_content
[debug] application - Response(Controller) : This is a response from post().
  
[debug] application - Request(ActionCreator) : play.http.HttpEntity$Strict@21b69a9
[debug] application - Request(Filter) : POST /api/post
[debug] application - Response(Filter) : play.http.HttpEntity$Strict@d1c58c

へぇ、そんな順番なんだぁ、というただそれだけです。
こちらからの報告は以上です。