Logging HTTP Request Time in RESTEasy

I wanted to log the time it took to complete requests sent to our HTTP API. This particular API uses JBoss’ RESTEasy framework for REST-like request dispatching. I wanted to intercept the request prior to it being executed:

class MyInterceptor {
  Logger logger;
  StopWatch timer;
  public void intercept() {
    timer.start();
    doRequest(); // RESTEasy executes what the API call is
    logger.info(timer.stop()); // Stop the timer and log the API call for the request url
  }
}

Alas, RESTEasy does not seem to provide the ability to insert your own code in the routing/dispatching process. However, it does have the ability to create pre and post filter classes (called Interceptors) that are executed before and after a request. The mechanism works as follows:

// more pseudo code
for (preFilter : preFilters) {
  preFilter.doWork();
}

doRequest();

for (postFilter : postFilters) {
  postFilter.doWork();
}

I ended up using the following hack to time my API requests:

class CallTimingPreInterceptor implements PreProcessInterceptor {
  public ServerResponse preProcess(HttpRequest request, ResourceMethod method) {
    StopWatch timer;
    timer.start();
    request.addAttribute("timer", timer);
  }
}

class CallTimingPostInterceptor implements PostProcessInterceptor {
  private @UriContext HTTPRequest request;

  public void postProcess(ServerResponse response) {
    StopWatch timer = request.getAttribute("timer");
    logger.info(timer.stop());
  }
}

// this example does not check for nulls etc, it's an example

I set a StopWatch on the request and start it inside the pre-filter. During post-filtering, I inject the request into the filter, grab the timer, stop it and log the duration. It’s totally hacky, but at least I don’t have to add timing code into the our RESTEasy classes and I don’t have to introduce an AOP framework into the codebase. Definitely not my favorite implementation, but it’ll do for now.