Groovy Method Tracer Transformer

In general I don't find trace logs for entering and exiting a method to be very useful, but occasionally I work with teams that do. There are great options using Spring or AspectJ, but I was in a Groovy project that didn't have either readily available. So, it made me wonder if we could just use AST transformations to build the loggers at compile time. Of course, as awesome as Groovy is, it's not hard. It already has a really cool feature to add code guards for logging statements, now I want to inject new logging statements into the code.

Groovy has an option to wrap methods on individual classes (see this metaClass example), but I was hoping to use an annotation, using an implementation of the ASTTransformation, to selectively add logging on methods. Thankfully, Groovy has an example in their documentation
(search for WithLogging). So here's a slightly tweaked implementation.

WithTracer.java

@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD})
@GroovyASTTransformationClass(classes = {WithTracerAstTransformer.class})
public @interface WithTracer {
  // marker annotation
}

WithTracerASTTransformer.groovy

import groovy.transform.CompileStatic
import org.codehaus.groovy.ast.ASTNode
import org.codehaus.groovy.ast.MethodNode
import org.codehaus.groovy.ast.expr.ArgumentListExpression
import org.codehaus.groovy.ast.expr.ConstantExpression
import org.codehaus.groovy.ast.expr.MethodCallExpression
import org.codehaus.groovy.ast.expr.VariableExpression
import org.codehaus.groovy.ast.stmt.BlockStatement
import org.codehaus.groovy.ast.stmt.ExpressionStatement
import org.codehaus.groovy.ast.stmt.ReturnStatement
import org.codehaus.groovy.ast.stmt.Statement
import org.codehaus.groovy.control.CompilePhase
import org.codehaus.groovy.control.SourceUnit
import org.codehaus.groovy.transform.ASTTransformation
import org.codehaus.groovy.transform.GroovyASTTransformation

@CompileStatic
@GroovyASTTransformation(phase=CompilePhase.SEMANTIC_ANALYSIS)
class WithTracerAstTransformer implements ASTTransformation {
  @Override
  void visit(ASTNode[] nodes, SourceUnit sourceUnit) {
    MethodNode method = (MethodNode) nodes[1]

    def startMessage = createPrintlnAst("Starting $method.name")
    def endMessage = createPrintlnAst("Ending $method.name")

    def existingStatements = ((BlockStatement)method.code).statements
    existingStatements.add(0, startMessage)

     //insert the trace before the return statement, or as the last statement
    if (existingStatements.last() instanceof ReturnStatement) {
      existingStatements.add(existingStatements.size() - 1, endMessage)
    } else {
      existingStatements.add(endMessage)
    }
  }

  private static Statement createPrintlnAst(String message) {
    new ExpressionStatement(
      new MethodCallExpression(
        new VariableExpression("log"),
        new ConstantExpression("trace"),
        new ArgumentListExpression(new ConstantExpression(message))
        )
    )
  }
}

The only problem with this simple approach is that the Groovy logging annotation which adds the code guards are applied before this new annotation. So if I wanted this to be production ready, the transformer would probably need to extend the existing Groovy logging transformer in some way. For my purposes though, I was able to convince the team that looking in AppDynamics to see the method execution path was a better option.

The other problem I ran into is that Eclipse is stupid. Every time that I clean the project the classes get wiped out and the Eclipse compiler fails on any class that was trying to use the annotation. So I had to put the code for this in a separate project.

Probably not something I'd use, but it was a really interesting experiment with ASTTransformation that might have other possibilities.

Read more