jcabi-aspects – Logging Java method executions

Logging Java method executions

Read this blog post first: Java Method Logging with AOP and Annotations

Annotate your methods with @Loggable annotation and every time they are called, your SLF4J logging facility will receive a message with the details of execution and the total execution time:

public class Resource {
  @Loggable(Loggable.DEBUG)
  public String load(URL url) {
    return url.openConnection().getContent();
  }
}

Something like this will appear in the log:

[DEBUG] #load('http://www.google.com'): returned "<html ..." in 23ms

If a method throws an exception, it is also logged.

Methods toString() of your method arguments and its return value are used to compose a log line. Too long of texts are trimmed to 100 characters in order to make log lines compact. Since version 0.7.13, it's possible to disable this trimming mechanism with an extra trim argument of the annotation.

Note: Due to limitations of AspectJ, constructors are not supported at the moment.

Since version 0.7.13, an entire class can be annotated. In this case, all public (!) methods will be logged (except toString(), hashCode(), and equals(Object)).

public class Resource {
  @Loggable(Loggable.DEBUG)
  public class Foo {
    // All methods of the class will be logged.
  }
}

If both a class and a method are annotated, method annotation has a higher priority.

Since version 0.7.6, you can specify a time limit in seconds as a maximum execution time of a method. If this limit is reached, a logging level is increased to WARN and method slowness is reported. Since version 0.7.14, you can change time unit as well:

public class Resource {
  @Loggable(limit = 200, unit = TimeUnit.MILLISECONDS)
  public void run() {
    // Something that should not take more than 200 msec.
  }
}

Since version 0.7.16, you can get log lines not only when method execution is done, but also when it has just started:

public class Resource {
  @Loggable(prepend = true)
  public void run() {
    // Something that takes too long.
  }
}

In this case, two log lines will be recorded. One when the method has just started and the other one when it returns the output.

Since version 0.7.18, you can ignore certain exception types. They won't be logged when thrown and won't pollute the log. Sometimes, exceptions don't mean fatal errors and should not be visible in logs. For example, in JAX-RS, applications where WebApplicationException is used to redirect a user to another page and not an indicator of an application error:

@Path("/")
public class JaxRsResource {
  @GET
  @Loggable(ignore = WebApplicationException.class)
  public String get() {
    if (/* not a logged in user */) {
      throw new WebApplicationException(Response.seeOther(/* URI */));
    }
  }
}

Since version 0.7.19, it is possible to skip either arguments, or result part of the log message in order to make it more compact by using skipArgs and skipResult arguments of @Loggable annotation:

public class VerboseClass {
  @Loggable(skipResult = true)
  public List<String> get(String name) {
    // Returns a long list of texts which are not
    // important and should not pollute the log.
  }
}

Since version 0.8.1, it is possible to add result of toString() method into the log line by setting logThis to true in @Loggable annotaton:

public class LoggingThis {
  private final String name = "John";

  @Loggable(logThis = true)
  public List<String> get(String name) {
    // Returns a long list of texts which are not
    // important and should not pollute the log.
  }

  public String toString() {
    return String.format("{name=%s}", this.name);
  }
}

Since version 0.18, it is possible to use a custom target logger for logging in @Loggable, by setting name parameter to the desired logger. When this parameter is not set (or set to an empty string) target logger will be of the method class (this is the same behaviour as before 0.18 release).

public class LoggingName {
  @Loggable(name = "com.foo.my-custom-logger")
  public List<String> get(String name) {
      // will log to com.foo.my-custom-logger

Since version 0.18, it is possible to specify the precision of measured execution time by providing the number of fractional digits in precision parameter of @Loggable. The default precision is set to 2.

public class LoggingPrecision {
  @Loggable(precision = 4)
  public List<String> get(String name) {
      // time logged will have 4 fractional digits
  }
}

The mechanism is implemented with AOP/AspectJ. Read how to integrate it into your pom.xml.