feat: refactor and add time annotation

pom.xml

@@ -75,11 +75,6 @@
             <artifactId>micronaut-inject</artifactId>
             <scope>compile</scope>
         </dependency>
-        <dependency>
-            <groupId>io.micronaut</groupId>
-            <artifactId>micronaut-jackson-databind</artifactId>
-            <scope>compile</scope>
-        </dependency>
         <dependency>
             <groupId>ch.qos.logback</groupId>
             <artifactId>logback-classic</artifactId>

src/main/java/me/goudham/trace/Trace.java

@@ -1,16 +0,0 @@
-package me.goudham.trace;
-
-import io.micronaut.aop.Around;
-import jakarta.inject.Qualifier;
-
-import java.lang.annotation.ElementType;
-import java.lang.annotation.Retention;
-import java.lang.annotation.RetentionPolicy;
-import java.lang.annotation.Target;
-
-@Qualifier
-@Target(ElementType.METHOD)
-@Retention(RetentionPolicy.RUNTIME)
-@Around
-public @interface Trace {
-}

src/main/java/me/goudham/trace/annotation/Time.java

@@ -0,0 +1,26 @@
+package me.goudham.trace.annotation;
+
+import io.micronaut.aop.Around;
+import jakarta.inject.Qualifier;
+import me.goudham.trace.shared.TimeInterpreter;
+
+import java.lang.annotation.ElementType;
+import java.lang.annotation.Retention;
+import java.lang.annotation.RetentionPolicy;
+import java.lang.annotation.Target;
+
+/**
+ * {@code @Time} calculates the execution time of the
+ * annotated method and logs it.
+ * <p></p>
+ * <p>It is important to note that these logs will only be seen if {@link System.Logger}
+ * is configured to log at {@link System.Logger.Level#TRACE}</p>
+ *
+ * @see TimeInterpreter
+ */
+@Qualifier
+@Target(ElementType.METHOD)
+@Retention(RetentionPolicy.RUNTIME)
+@Around
+public @interface Time {
+}

src/main/java/me/goudham/trace/annotation/Trace.java

@@ -0,0 +1,26 @@
+package me.goudham.trace.annotation;
+
+import io.micronaut.aop.Around;
+import jakarta.inject.Qualifier;
+import me.goudham.trace.shared.TraceInterpreter;
+
+import java.lang.annotation.ElementType;
+import java.lang.annotation.Retention;
+import java.lang.annotation.RetentionPolicy;
+import java.lang.annotation.Target;
+
+/**
+ * {@code @Trace} indicates that the current method will be monitored to allow
+ * logging when the method was entered and exited.
+ * <p></p>
+ * <p>It is important to note that these logs will only be seen if {@link System.Logger}
+ * is configured to log at {@link System.Logger.Level#TRACE}</p>
+ *
+ * @see TraceInterpreter
+ */
+@Qualifier
+@Target(ElementType.METHOD)
+@Retention(RetentionPolicy.RUNTIME)
+@Around
+public @interface Trace {
+}

src/main/java/me/goudham/trace/domain/LogType.java

@@ -0,0 +1,19 @@
+package me.goudham.trace.domain;
+
+import me.goudham.trace.shared.TimeInterpreter;
+import me.goudham.trace.shared.TraceInterpreter;
+import me.goudham.trace.service.LoggingService;
+
+/**
+ * Represents each type that's used for logging
+ *
+ * @see LoggingService
+ * @see TraceInterpreter
+ * @see TimeInterpreter
+ */
+public enum LogType {
+    ENTERING,
+    EXITING,
+    ERROR,
+    EXECUTION_TIME
+}

src/main/java/me/goudham/trace/interceptor/TraceInterpreter.java

@@ -1,45 +0,0 @@
-package me.goudham.trace.interceptor;
-
-import io.micronaut.aop.InterceptorBean;
-import io.micronaut.aop.MethodInterceptor;
-import io.micronaut.aop.MethodInvocationContext;
-import jakarta.inject.Singleton;
-import me.goudham.trace.Trace;
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-
-import java.util.Arrays;
-import java.util.stream.Collectors;
-
-@Singleton
-@InterceptorBean(Trace.class)
-public class TraceInterpreter implements MethodInterceptor<Object, Object> {
-
-    @Override
-    public Object intercept(MethodInvocationContext<Object, Object> context) {
-        Logger logger = LoggerFactory.getLogger(context.getDeclaringType());
-        if (logger.isTraceEnabled()) {
-            return executeMethod(context, logger);
-        }
-        return context.proceed();
-    }
-
-    protected Object executeMethod(MethodInvocationContext<Object, Object> context, Logger logger) {
-        Object result;
-        String methodName = context.getMethodName();
-        String signature = Arrays.stream(context.getArguments())
-            .map(argument -> argument.getTypeName() + " " + argument.getName())
-            .collect(Collectors.joining(", "));
-
-        logger.trace("[ENTERING]: {}({})", methodName, signature);
-        try {
-            result = context.proceed();
-        } catch (Throwable throwable) {
-            logger.trace("[ERROR]: {}({})", methodName, signature);
-            throw throwable;
-        }
-        logger.trace("[EXITING]: {}({})", methodName, signature);
-
-        return result;
-    }
-}

src/main/java/me/goudham/trace/service/LoggingService.java

@@ -0,0 +1,30 @@
+package me.goudham.trace.service;
+
+import jakarta.inject.Singleton;
+import me.goudham.trace.domain.LogType;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+/**
+ * Encapsulates the built-in {@link Logger}
+ */
+@Singleton
+public class LoggingService {
+    private Logger logger;
+
+    public void trace(LogType logType, String method, String signature) {
+        logger.trace("[{}]: {}({})", logType.name(), method, signature);
+    }
+
+    public void trace(LogType logType, String method, String signature, long timeElapsed) {
+        logger.trace("[{}]: Elapsed execution time for {}({}) is {} milliseconds", logType.name(), method, signature, timeElapsed);
+    }
+
+    public void setLogger(Class<?> clazz) {
+        logger = LoggerFactory.getLogger(clazz);
+    }
+
+    public boolean isTraceEnabled() {
+        return logger.isTraceEnabled();
+    }
+}

src/main/java/me/goudham/trace/shared/Intercepter.java

@@ -0,0 +1,40 @@
+package me.goudham.trace.shared;
+
+import io.micronaut.aop.MethodInterceptor;
+import io.micronaut.aop.MethodInvocationContext;
+import me.goudham.trace.service.LoggingService;
+
+import java.util.Arrays;
+import java.util.stream.Collectors;
+
+abstract class Intercepter implements MethodInterceptor<Object, Object> {
+    final LoggingService loggingService;
+
+    Intercepter(LoggingService loggingService) {
+        this.loggingService = loggingService;
+    }
+
+    abstract Object logAndExecuteMethod(MethodInvocationContext<Object, Object> context);
+
+    @Override
+    public Object intercept(MethodInvocationContext<Object, Object> context) {
+        loggingService.setLogger(context.getDeclaringType());
+        if (loggingService.isTraceEnabled()) {
+            return logAndExecuteMethod(context);
+        }
+        return context.proceed();
+    }
+
+    /**
+     * {@link java.util.stream.Stream}'s over all method arguments,
+     * joining the type and name together into one string.
+     *
+     * @param context Object representing information about the annotated method
+     * @return {@code String} containing all method arguments separated by commas
+     */
+    String getArguments(MethodInvocationContext<Object, Object> context) {
+        return Arrays.stream(context.getArguments())
+            .map(argument -> argument.getTypeName() + " " + argument.getName())
+            .collect(Collectors.joining(", "));
+    }
+}

src/main/java/me/goudham/trace/shared/TimeIntercepter.java

@@ -0,0 +1,45 @@
+package me.goudham.trace.shared;
+
+import io.micronaut.aop.MethodInvocationContext;
+import jakarta.inject.Inject;
+import jakarta.inject.Singleton;
+import me.goudham.trace.annotation.Time;
+import me.goudham.trace.domain.LogType;
+import me.goudham.trace.service.LoggingService;
+
+import java.util.concurrent.TimeUnit;
+
+/**
+ * Intercepts the annotated method and logs out the
+ * execution time of the entire method.
+ *
+ * @see Time
+ */
+@Singleton
+class TimeIntercepter extends Intercepter {
+
+    @Inject
+    TimeIntercepter(LoggingService loggingService) {
+        super(loggingService);
+    }
+
+    /**
+     * Logs the execution time of the annotated method.
+     * The method name and signature are included within
+     * the log itself.
+     *
+     * @param context Object representing information about the annotated method
+     * @return Result of annotated method after execution
+     */
+    @Override
+    Object logAndExecuteMethod(MethodInvocationContext<Object, Object> context) {
+        long start = System.nanoTime();
+        Object result = context.proceed();
+        long finish = System.nanoTime();
+        long timeElapsed = TimeUnit.NANOSECONDS.toMillis(finish - start);
+
+        loggingService.trace(LogType.EXECUTION_TIME, context.getMethodName(), getArguments(context), timeElapsed);
+
+        return result;
+    }
+}

src/main/java/me/goudham/trace/shared/TimeInterpreter.java

@@ -0,0 +1,31 @@
+package me.goudham.trace.shared;
+
+import io.micronaut.aop.InterceptorBean;
+import io.micronaut.aop.MethodInterceptor;
+import io.micronaut.aop.MethodInvocationContext;
+import jakarta.inject.Inject;
+import jakarta.inject.Named;
+import jakarta.inject.Singleton;
+import me.goudham.trace.annotation.Time;
+
+/**
+ * Intercepts the annotated method and logs out the
+ * execution time of the entire method.
+ *
+ * @see Time
+ */
+@Singleton
+@InterceptorBean(Time.class)
+public class TimeInterpreter implements MethodInterceptor<Object, Object> {
+    private final Intercepter intercepter;
+
+    @Inject
+    public TimeInterpreter(@Named("Time") Intercepter intercepter) {
+        this.intercepter = intercepter;
+    }
+
+    @Override
+    public Object intercept(MethodInvocationContext<Object, Object> context) {
+        return intercepter.intercept(context);
+    }
+}

src/main/java/me/goudham/trace/shared/TraceIntercepter.java

@@ -0,0 +1,49 @@
+package me.goudham.trace.shared;
+
+import io.micronaut.aop.MethodInvocationContext;
+import jakarta.inject.Inject;
+import jakarta.inject.Singleton;
+import me.goudham.trace.annotation.Trace;
+import me.goudham.trace.domain.LogType;
+import me.goudham.trace.service.LoggingService;
+
+/**
+ * Intercepts the annotated method and logs out when it
+ * was entered and exited.
+ *
+ * @see Trace
+ */
+@Singleton
+class TraceIntercepter extends Intercepter {
+
+    @Inject
+    TraceIntercepter(LoggingService loggingService) {
+        super(loggingService);
+    }
+
+    /**
+     * Logs before and after the method is called.
+     * The method name and signature are included
+     * within the log itself.
+     *
+     * @param context Object representing information about the annotated method
+     * @return Result of annotated method after execution
+     */
+    @Override
+    Object logAndExecuteMethod(MethodInvocationContext<Object, Object> context) {
+        Object result;
+        String name = context.getMethodName();
+        String signature = getArguments(context);
+
+        loggingService.trace(LogType.ENTERING, name, signature);
+        try {
+            result = context.proceed();
+        } catch (Throwable throwable) {
+            loggingService.trace(LogType.ERROR, name, signature);
+            throw throwable;
+        }
+        loggingService.trace(LogType.EXITING, name, signature);
+
+        return result;
+    }
+}

src/main/java/me/goudham/trace/shared/TraceInterpreter.java

@@ -0,0 +1,31 @@
+package me.goudham.trace.shared;
+
+import io.micronaut.aop.InterceptorBean;
+import io.micronaut.aop.MethodInterceptor;
+import io.micronaut.aop.MethodInvocationContext;
+import jakarta.inject.Inject;
+import jakarta.inject.Named;
+import jakarta.inject.Singleton;
+import me.goudham.trace.annotation.Trace;
+
+/**
+ * Intercepts the annotated method and logs out when it
+ * was entered and exited.
+ *
+ * @see Trace
+ */
+@Singleton
+@InterceptorBean(Trace.class)
+public class TraceInterpreter implements MethodInterceptor<Object, Object> {
+    private final Intercepter traceIntercepter;
+
+    @Inject
+    public TraceInterpreter(@Named("Trace") Intercepter traceIntercepter) {
+        this.traceIntercepter = traceIntercepter;
+    }
+
+    @Override
+    public Object intercept(MethodInvocationContext<Object, Object> context) {
+        return traceIntercepter.intercept(context);
+    }
+}

src/main/resources/logback.xml

@@ -1,5 +1,4 @@
 <configuration>
-
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
         <withJansi>true</withJansi>
         <!-- encoders are assigned the type
@@ -10,7 +9,7 @@
         </encoder>
     </appender>
 
-    <root level="info">
+    <root level="TRACE">
         <appender-ref ref="STDOUT"/>
     </root>
 </configuration>

src/test/java/me/goudham/trace/shared/TimeIntercepterTest.java

@@ -0,0 +1,76 @@
+package me.goudham.trace.shared;
+
+import io.micronaut.aop.MethodInvocationContext;
+import io.micronaut.core.type.Argument;
+import io.micronaut.test.annotation.MockBean;
+import io.micronaut.test.extensions.junit5.annotation.MicronautTest;
+import jakarta.inject.Inject;
+import jakarta.inject.Named;
+import me.goudham.trace.domain.LogType;
+import me.goudham.trace.service.LoggingService;
+import org.junit.jupiter.api.Test;
+
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.is;
+import static org.junit.jupiter.api.Assertions.*;
+import static org.mockito.Mockito.*;
+import static org.mockito.Mockito.verifyNoMoreInteractions;
+
+@MicronautTest
+class TimeIntercepterTest {
+    @Inject
+    private MethodInvocationContext<Object, Object> methodInvocationContext;
+
+    @Inject
+    private LoggingService loggingService;
+
+    @Inject
+    @Named("Time")
+    private Intercepter sut;
+
+    @Test
+    void shouldNotProduceTraceLogsWhenTracingDisabled() {
+        when(methodInvocationContext.getDeclaringType()).thenReturn(Object.class);
+        when(loggingService.isTraceEnabled()).thenReturn(false);
+
+        sut.intercept(methodInvocationContext);
+
+        verify(methodInvocationContext, times(1)).getDeclaringType();
+        verify(methodInvocationContext, times(1)).proceed();
+        verifyNoMoreInteractions(methodInvocationContext);
+    }
+
+    @Test
+    void successfullyLogMethodExecutionTime() {
+        when(methodInvocationContext.getMethodName()).thenReturn("test");
+        when(methodInvocationContext.getArguments()).thenReturn(new Argument[0]);
+
+        sut.logAndExecuteMethod(methodInvocationContext);
+
+        verify(loggingService, times(1)).trace(eq(LogType.EXECUTION_TIME), eq("test"), eq(""), anyLong());
+        verifyNoMoreInteractions(loggingService);
+    }
+
+    @Test
+    void shouldNotLogMethodExecutionTimeWhenException() {
+        when(methodInvocationContext.getMethodName()).thenReturn("test");
+        when(methodInvocationContext.getArguments()).thenReturn(new Argument[0]);
+        RuntimeException actualException = new RuntimeException("Oh nyo~ Anyway");
+        when(methodInvocationContext.proceed()).thenThrow(actualException);
+
+        RuntimeException expectedException = assertThrows(RuntimeException.class, () -> sut.logAndExecuteMethod(methodInvocationContext));
+
+        assertThat(actualException, is(expectedException));
+        verifyNoInteractions(loggingService);
+    }
+
+    @MockBean(MethodInvocationContext.class)
+    MethodInvocationContext<Object, Object> methodInvocationContext() {
+        return mock(MethodInvocationContext.class);
+    }
+
+    @MockBean(LoggingService.class)
+    LoggingService loggingService() {
+        return mock(LoggingService.class);
+    }
+}

src/test/java/me/goudham/trace/shared/TraceIntercepterTest.java

@@ -1,12 +1,14 @@
-package me.goudham.trace.interceptor;
+package me.goudham.trace.shared;
 
 import io.micronaut.aop.MethodInvocationContext;
 import io.micronaut.core.type.Argument;
 import io.micronaut.test.annotation.MockBean;
 import io.micronaut.test.extensions.junit5.annotation.MicronautTest;
 import jakarta.inject.Inject;
+import jakarta.inject.Named;
+import me.goudham.trace.domain.LogType;
+import me.goudham.trace.service.LoggingService;
 import org.junit.jupiter.api.Test;
-import org.slf4j.Logger;
 
 import static org.hamcrest.MatcherAssert.assertThat;
 import static org.hamcrest.Matchers.is;
@@ -14,24 +16,27 @@ import static org.junit.jupiter.api.Assertions.assertThrows;
 import static org.mockito.Mockito.*;
 
 @MicronautTest
-class TraceInterpreterTest {
+class TraceIntercepterTest {
-    private final TraceInterpreter sut;
+    @Inject
-    private final MethodInvocationContext<Object, Object> methodInvocationContext = methodInvocationContext();
+    private MethodInvocationContext<Object, Object> methodInvocationContext;
-    private final Logger logger = logger();
 
     @Inject
-    public TraceInterpreterTest(TraceInterpreter sut) {
+    private LoggingService loggingService;
-        this.sut = sut;
+
-    }
+    @Inject
+    @Named("Trace")
+    private Intercepter sut;
 
     @Test
-    void shouldNotProduceTraceLogs() {
+    void shouldNotProduceTraceLogsWhenTracingDisabled() {
         when(methodInvocationContext.getDeclaringType()).thenReturn(Object.class);
+        when(loggingService.isTraceEnabled()).thenReturn(false);
 
         sut.intercept(methodInvocationContext);
 
         verify(methodInvocationContext, times(1)).getDeclaringType();
         verify(methodInvocationContext, times(1)).proceed();
+        verifyNoMoreInteractions(methodInvocationContext);
     }
 
     @Test
@@ -44,23 +49,26 @@ class TraceInterpreterTest {
             }
         );
 
-        sut.executeMethod(methodInvocationContext, logger);
+        sut.logAndExecuteMethod(methodInvocationContext);
 
-        verify(logger, times(1)).trace("[ENTERING]: {}({})", "test", "java.lang.String winston, java.lang.Boolean pigeon");
+        verify(loggingService, times(1)).trace(LogType.ENTERING, "test", "java.lang.String winston, java.lang.Boolean pigeon");
-        verify(logger, times(1)).trace("[EXITING]: {}({})", "test", "java.lang.String winston, java.lang.Boolean pigeon");
+        verify(loggingService, times(1)).trace(LogType.EXITING, "test", "java.lang.String winston, java.lang.Boolean pigeon");
+        verifyNoMoreInteractions(loggingService);
     }
 
     @Test
     void successfullyLogErrorWhenException() {
         when(methodInvocationContext.getMethodName()).thenReturn("test");
         when(methodInvocationContext.getArguments()).thenReturn(new Argument[0]);
-        RuntimeException actualException = new RuntimeException("Uh Oh! Something Went Wrong!");
+        RuntimeException actualException = new RuntimeException("Oh nyo~ Anyway");
         when(methodInvocationContext.proceed()).thenThrow(actualException);
 
-        RuntimeException expectedException = assertThrows(RuntimeException.class, () -> sut.executeMethod(methodInvocationContext, logger));
+        RuntimeException expectedException = assertThrows(RuntimeException.class, () -> sut.logAndExecuteMethod(methodInvocationContext));
 
         assertThat(actualException, is(expectedException));
-        verify(logger, times(1)).trace("[ERROR]: {}({})", "test", "");
+        verify(loggingService, times(1)).trace(LogType.ENTERING, "test", "");
+        verify(loggingService, times(1)).trace(LogType.ERROR, "test", "");
+        verifyNoMoreInteractions(loggingService);
     }
 
     @MockBean(MethodInvocationContext.class)
@@ -68,8 +76,8 @@ class TraceInterpreterTest {
         return mock(MethodInvocationContext.class);
     }
 
-    @MockBean(Logger.class)
+    @MockBean(LoggingService.class)
-    Logger logger() {
+    LoggingService loggingService() {
-        return mock(Logger.class);
+        return mock(LoggingService.class);
     }
 }