Design pattern for logging entry and exit of methods?

Question

I have an overall design and architecture question. After looking at design patterns (decorators, chain of commands, and so on) it is still unclear to me.

Requirement: I would like to have logging for both entry and exit of my methods.

As of now, all my methods looks like:

public SomeReturnType someMethod1( SomeParameter someParameter ) {
    LOGGER.info( "{someMethod1}[START someMethod1 compute]" );

    doSomeComputationFor(someParameter);
    SomeReturnType result = getSomeResult();

    LOGGER.info( "{someMethod1}[END someMethod1 compute]" );

    return result;
}

public SomeOtherReturnType someMethod2( SomeOtherParameter someOtherParameter ) {
    LOGGER.info( "{someMethod2}[START someMethod2 compute]" );

    maybeDoSomeDBOperation(someOtherParameter);
    SomeOtherReturnType result = getSomeOtherResult();

    LOGGER.info( "{someMethod2}[END someMethod2 compute]" );

    return result;
}

(Below the logging, I am also using some KPI library to send some timestamp, like StatsD)

All structures are really of the form:

public Foo method( Bar bar ) {
    //1 do some logging as the method starts, and also send some KPI
    LOGGER.info( "{method}[START method compute]" );

    //2 do some computation and actual business logic

    //3 do some logging the confirm the mothods has reached the end + send some other KPI like time elapsed
    LOGGER.info( "{method}[END method compute]" );

    return result;
}

Now, looking at my project, I have some 290 methods who are following the EXACT same structure.

Is there a clever way of resolving this? Maybe with a nice pattern? Some annotations? Aspects? I am open to suggestion as I believe there is definitely a better solution than my current one.

Answer 1

A possible solution is using your dependency injector + annotations.

Here you have an example on how to implement what you want using Weld in a JavaSE application.

You need to add this dependency:

<dependency>
    <groupId>org.jboss.weld.se</groupId>
    <artifactId>weld-se-core</artifactId>
    <version>3.1.0.Final</version>
</dependency>

Then create an annotation that it will be use to point those methods you want to log.

package org.loggable;

import javax.interceptor.InterceptorBinding;
import java.lang.annotation.ElementType;
import java.lang.annotation.Inherited;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Target({ElementType.TYPE, ElementType.METHOD})
@Inherited
@InterceptorBinding
@Retention(RetentionPolicy.RUNTIME)
public @interface Loggable {
}

Create the interceptor

package org.loggable;

import javax.interceptor.AroundInvoke;
import javax.interceptor.Interceptor;
import javax.interceptor.InvocationContext;
import java.util.logging.Logger;

@Loggable
@Interceptor
public class LoggableInterceptor {

    @AroundInvoke
    public Object logMethod(InvocationContext context) throws Exception {
        Logger logger = Logger.getLogger(context.getTarget().getClass().getSimpleName());

        logger.info("Starting method: " + context.getMethod().getName());
        Object response = context.proceed();
        logger.info("Finished method: " + context.getMethod().getName());
        return response;

    }
}

As you see @AroundInvoke allows us to control when entering a method and exiting.

We have to inform Weld that there is a new Interceptor, we do so by adding beans.xml in META-INF folder.

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://xmlns.jcp.org/xml/ns/javaee"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee
       http://xmlns.jcp.org/xml/ns/javaee/beans_1_1.xsd"
       bean-discovery-mode="all">
    <interceptors>
        <class>org.loggable.LoggableInterceptor</class>
    </interceptors>
</beans>

Lastly we need to call our entity through Weld as it is in charge of creating and execute interceptors.

package org.loggable;

import javax.enterprise.inject.se.SeContainer;
import javax.enterprise.inject.se.SeContainerInitializer;
import java.io.IOException;
import java.util.logging.Logger;

public class Main {
    public static void main(String... args) throws IOException {
        SeContainer seContainer = SeContainerInitializer.newInstance()
                .initialize();

        Main main = seContainer.select(Main.class).get();
        main.loggableMethod();

        seContainer.close();
    }


    @Loggable
    public void loggableMethod() {
        Logger.getLogger(Main.class.getSimpleName()).info("Inside method.");
    }
}

And you will get an output like:

[2019-04-06 11:07:20] [INFO   ] Starting method: loggableMethod 
[2019-04-06 11:07:20] [INFO   ] Inside method. 
[2019-04-06 11:07:20] [INFO   ] Finished method: loggableMethod 

This is project structure in case of need.

Note: In case you are in a JavaEE project, all related to Weld creation is managed by your container.