Il y a un article qui explique les bases de l'AOP avec Guice ici.
Il faut ces dépendances :
- Guice, pour le moteur d'injection, et qui permet également de faire de l'AOP.
com.google.inject
guice
3.0 - Slf4j, comme moteur de logging (avec logback en l'occurence comme implémentation).
- AOP, pour l'interface MethodInterceptor
On commence par créer une annotation :
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Log {
}
On créait l'implémentation de l'interception avec la classe LogInterceptor :
public class LogInterceptor implements MethodInterceptor {
public Object invoke(MethodInvocation invocation) throws Throwable {
}
}
Et on fait l'association dans le module Guice :
public class MyModule extends AbstractModule {
@Override
protected void configure() {
bindInterceptor(Matchers.any(), Matchers.annotatedWith(Log.class),
new LogInterceptor());
}
}
Une contrainte est que bien évidemment la méthode sur laquelle on rajoute cette annotation doit faire parti d'une classe elle-même injectée par Guice.
Et rajouter l'annotation sur la méthode à tracer :
public class MyService {
@Log
public String getAvailableCode(Code code) {
switch (code) {
case FIRST:
return "my first code";
case SECOND:
return "my second code";
default:
return "null";
}
}
}
Maintenant on passe à l'implémentation de la classe LogInterceptor, on commence par récupérer le logger de la classe de la méthode tracée :
public class LogInterceptor implements MethodInterceptor {
public Object invoke(MethodInvocation invocation) throws Throwable {
Method method = invocation.getMethod();
Class declaringClass = method.getDeclaringClass();
Logger logger = LoggerFactory.getLogger(declaringClass);
}
}
Et avant de tracer quelquechose, on vérifie si le niveau de log est activé, sinon on renvoie directement le résultat :
if (!logger.isDebugEnabled()) {
return invocation.proceed();
}
Sinon on trace l'appel est les paramètres passés à la méthode :
StringBuilder sb = new StringBuilder();
sb.append(method.getName()).append("()").append("[ENTER]");
Object[] arguments = invocation.getArguments();
if (arguments != null && arguments.length != 0) {
sb.append("[");
for (int i = 0; i < arguments.length; i++) {
sb.append("[argument(").append(i).append(")=\"") .append(arguments[i]).append("\"]");
}
sb.append("]");
}
logger.debug(sb.toString());
Et le résultat de la méthode :
Object proceed = invocation.proceed();
if (profile) {
stopWatch.stop();
}
sb = new StringBuilder();
sb.append(method.getName()).append("()").append("[EXIT ]");
sb.append("[return=\"").append(proceed).append("\"]");
if (profile) {
sb.append(" in ").append(stopWatch.getElapsedTime()).append(" ms");
}
logger.debug(sb.toString());
return proceed;
Et dans les logs :
15:48:42.382 [main] DEBUG net.antoine.aopguice.MyService - getAvailableCode()[ENTER][[argument(0)="FIRST"]]
15:48:42.424 [main] DEBUG net.antoine.aopguice.MyService - getAvailableCode()[EXIT ][return="my first code"]
Après le premier problème sur lequel on peut tomber est le cas où la méthode renvoie une exception comme par exemple ici :
@Log
public void throwException() {
throw new IllegalArgumentException("just for test");
}
Dans ce cas, on catche l'erreur, logue l'exception et on la renvoie :
Exception exception = null;
Object proceed = null;
try {
proceed = invocation.proceed();
} catch (Exception e) {
exception = e;
} finally {
sb = new StringBuilder();
sb.append(method.getName()).append("()").append("[EXIT ]");
if (exception == null) {
sb.append("[return=\"").append(proceed).append("\"]");
} else {
sb.append("[throws exception :").append(exception.toString())
.append("]");
}
logger.debug(sb.toString());
if (exception != null) {
throw exception;
}
}
return proceed;
16:01:04.594 [main] DEBUG net.antoine.aopguice.MyService - throwException()[ENTER]
16:01:04.603 [main] DEBUG net.antoine.aopguice.MyService - throwException()[EXIT ][throws exception :java.lang.IllegalArgumentException: just for test]
Maintenant un élément intéressant serait de tracer le temps d'éxécution de la méthode, on va utiliser pour celà Perf4j :
Idéalement, on aimerait que ce soit une option désactivé par défaut puisque inutile dans la plupart des cas. On rajoute une attribut à l'annotation :
public @interface Log {
/**
* Active timing execution if set to true, false by default.
*/
boolean profile() default false;
}
Et on va récupérer ce paramètre dans la méthode d'interception :
Log annotation = method.getAnnotation(Log.class);
boolean profile = false;
if (annotation != null) {
profile = annotation.profile();
}
StopWatch stopWatch = null;
if (profile) {
stopWatch = new LoggingStopWatch(method.getName());
}
if (profile) {
stopWatch.start();
}
Object proceed = null; try { proceed = invocation.proceed(); } catch (Exception e) { exception = e; } finally { if (profile) { stopWatch.stop(); }
//etc
if (profile) {
sb.append(" in ").append(stopWatch.getElapsedTime())
.append(" ms");
}
//etc
}
Et avec cette méthode :
@Log(profile = true)
public void traceTime() throws InterruptedException {
Random random = new Random();
int nextInt = random.nextInt(100);
Thread.sleep(50 + nextInt);
}
On obtient ces logs :
16:22:11.759 [main] DEBUG net.antoine.aopguice.MyService - traceTime()[ENTER]
start[1307283731759] time[117] tag[traceTime]
16:22:11.877 [main] DEBUG net.antoine.aopguice.MyService - traceTime()[EXIT ][return="null"] in 117 ms
Après on pourrait rajouter un attribut dans l'annotation pour pouvoir loguer en info, on rajouter un message à rajouter dans les traces. N'hésitez pas à rajouter un commentaire si vous avez d'autres idées.
