Pitfalls using AspectJ for logging Spring MVC requests

In general AspectJ is a great tool for logging. The logging code is non-invasive and its easy to use. You declare your pointcut for the methods you want to append log functionality to, can access method fields in the advice and log the incoming request as well as the outgoing response.

Consider the following setup in a typical Spring MVC envirnoment:

@RequestMapping(value = "post", method = RequestMethod.POST)
@ResponseBody
public List<String> post(final HttpServletRequest request,
final HttpServletResponse response)
throws Exception {
...
}

The advice method could look as follows:

public Object aroundAdvice(ProceedingJoinPoint pjp) throws Throwable {
HttpServletRequest request = null;
Object[] args = pjp.getArgs();
for (int i = 0; i < args.length; i++) {
  if (args[i] instanceof HttpServletRequest) {
    request = (HttpServletRequest) args[i];
  }
}
if (request != null) {
// read request body
  StringBuffer sb = new StringBuffer();
  String line = null;
  try {
    BufferedReader reader = request.getReader();
    while ((line = reader.readLine()) != null){
      sb.append(line);
    }
  } catch (Exception e){ /*error*/ }
  // log everything here
  // ...
}
}

The Problems come, when you want to access the HttpServletRequest and read the headers, parameters or the body. Those information are available through a stream. The nature of streams is that you can only read them once. So in this example the logger will perfectly log the request body, but after that it will be empty and your post method will receive and empty body since you already read it. You have the same problem if you define your logger in the filter chain of the dispatcher servlets.

The solution is to wrap the incoming request into another object that caches the content stream.

public class MultiReadHttpServletRequest extends HttpServletRequestWrapper {
 private ByteArrayOutputStream cachedBytes;

 public MultiReadHttpServletRequest(HttpServletRequest request) {
 super(request);
 }

 @Override
 public ServletInputStream getInputStream() throws IOException {
 if (cachedBytes == null)
 cacheInputStream();

 return new CachedServletInputStream();
 }

 @Override
 public BufferedReader getReader() throws IOException{
 return new BufferedReader(new InputStreamReader(getInputStream()));
 }

 private void cacheInputStream() throws IOException {
 /* Cache the inputstream in order to read it multiple times. For
 * convenience, I use apache.commons IOUtils
 */
 cachedBytes = new ByteArrayOutputStream();
 IOUtils.copy(super.getInputStream(), cachedBytes);
 }

 /* An inputstream which reads the cached request body */
 public class CachedServletInputStream extends ServletInputStream {
 private ByteArrayInputStream input;

 public CachedServletInputStream() {
 /* create a new input stream from the cached request body */
 input = new ByteArrayInputStream(cachedBytes.toByteArray());
 }

 @Override
 public int read() throws IOException {
 return input.read();
 }
 }
}

source: http://stackoverflow.com/a/17129256/1969813

Now the advice looks like this:

public Object aroundAdvice(ProceedingJoinPoint pjp) throws Throwable {
HttpServletRequest request = null;
Object[] args = pjp.getArgs();
for (int i = 0; i < args.length; i++) {
  if (args[i] instanceof HttpServletRequest) {
    request = (HttpServletRequest) args[i];
  }
}
if (request != null) {
 MultiReadHttpServletRequest multiReadRequest = new MultiReadHttpServletRequest(
 request);
// read request body
  StringBuffer sb = new StringBuffer();
  String line = null;
  try {
    BufferedReader reader = multiReadRequest .getReader();
    while ((line = reader.readLine()) != null){
        sb.append(line);
    } 
  } catch (Exception e){ /*error*/ } 
// log everything here // ...
 Object result = pjp.proceed(args);
 // log result
 // ..
 return result; 
}
return pjp.proceed(pjp.getArgs()); 
} 

You think why would you even want to access the HttpServletRequest, when Spring provides you with such very comfortable annotations like @RequestBody, @RequestHeader or @RequstParam, so your original method might look like this:

@RequestMapping(value = "post", method = RequestMethod.POST)
@ResponseBody
public List<String> post(
@RequestBody final String body,
final HttpServletRequest request,
final HttpServletResponse response)
throws Exception {
...
}

In AspectJ you can match parameters by type, or by order, or even by annotation. Then you can access the parameter in the advice, as shown here:
@AspectJ cheat sheet

The catch is if you want to match several or even all of your controller methods with a pointcut. If they have parameters of the same type, matching by type is not an option. If the parameter order differs from method to method, matching by order is also not possible. Whats left is matching by annotation. But if you have several times the same annotation, this also won’t work. So the remaining and most flexible option is to directly access the HttpServletRequest, as shown above.

The provided advice will not work for the code above with the @ResponseBody annotation. Why?
The execution order now is:
1. Incoming request is handled by the filter chain provided by the dispatcher servlets
2. The dispatcher servlet forwards the request to the right controller method.
3. The pointcut of the aspect matches the method and the code is injected into the method body. (If LTW. On CTW the code is already in place)
4. The @RequestBody annotation is executed and reads the body from the request into the variable.
5. The injected advice is executed
6. The post method body is executed.

On 5. we access the request which has already been read in 4 and thus is empty. So the problem is, that the code of the annotations is executed earlier than the advice code.

If you encounter that problem and you cannot or don’t want to change the controllers, you have to find the method parameter somehow. Again, you could do this using the pointcut, but some methods might not have that annotation.

The most stable and bulletproof approach is this:


private void logCall(ProceedingJoinPoint pjp, MultiReadHttpServletRequest request) { 
  StringBuilder sb = new StringBuilder();
  String signature = pjp.getSignature().toShortString();
  MethodSignature ms = (MethodSignature) pjp.getSignature();
  Method m = ms.getMethod();
  Annotation[][] parameterAnnotations = m.getParameterAnnotations();
  String requestBody = "";
  for (int i = 0; i < parameterAnnotations.length; i++) {
    Annotation[] annotations = parameterAnnotations[i];
    for (Annotation annotation : annotations) {
      if (annotation.annotationType() == RequestBody.class) {
        requestBody = (String) (pjp.getArgs())[i];
      }
    }
  }
// logging here....
}

Advertisements

Kommentar verfassen

Trage deine Daten unten ein oder klicke ein Icon um dich einzuloggen:

WordPress.com-Logo

Du kommentierst mit Deinem WordPress.com-Konto. Abmelden / Ändern )

Twitter-Bild

Du kommentierst mit Deinem Twitter-Konto. Abmelden / Ändern )

Facebook-Foto

Du kommentierst mit Deinem Facebook-Konto. Abmelden / Ändern )

Google+ Foto

Du kommentierst mit Deinem Google+-Konto. Abmelden / Ändern )

Verbinde mit %s