feat: Performance logging (#15)

build.gradle.kts

@@ -70,6 +70,16 @@ tasks.withType<Test> {
   finalizedBy(tasks.jacocoTestReport)
 }
 
+val mockitoAgent = configurations.create("mockitoAgent")
+dependencies {
+  mockitoAgent("org.mockito:mockito-core") { isTransitive = false }
+}
+tasks {
+  test {
+    jvmArgs("-javaagent:${mockitoAgent.asPath}")
+  }
+}
+
 tasks.jacocoTestReport {
   dependsOn(tasks.test)
   reports {

src/main/java/it/gov/pagopa/pu/classification/config/RestTemplateConfig.java

@@ -0,0 +1,67 @@
+package it.gov.pagopa.pu.classification.config;
+
+import it.gov.pagopa.pu.classification.performancelogger.RestInvokePerformanceLogger;
+import jakarta.annotation.Nonnull;
+import lombok.extern.slf4j.Slf4j;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.springframework.beans.factory.annotation.Value;
+import org.springframework.boot.autoconfigure.web.client.RestTemplateBuilderConfigurer;
+import org.springframework.boot.web.client.RestTemplateBuilder;
+import org.springframework.context.annotation.Bean;
+import org.springframework.context.annotation.Configuration;
+import org.springframework.http.HttpMethod;
+import org.springframework.http.HttpStatusCode;
+import org.springframework.http.client.ClientHttpResponse;
+import org.springframework.lang.Nullable;
+import org.springframework.web.client.DefaultResponseErrorHandler;
+import org.springframework.web.client.HttpStatusCodeException;
+import org.springframework.web.client.ResponseErrorHandler;
+
+import java.io.IOException;
+import java.net.URI;
+import java.time.Duration;
+
+@Slf4j
+@Configuration(proxyBeanMethods = false)
+public class RestTemplateConfig {
+    private final int connectTimeoutMillis;
+    private final int readTimeoutHandlerMillis;
+
+    public RestTemplateConfig(
+            @Value("${rest.default-timeout.connect-millis}") int connectTimeoutMillis,
+            @Value("${rest.default-timeout.read-millis}") int readTimeoutHandlerMillis) {
+        this.connectTimeoutMillis = connectTimeoutMillis;
+        this.readTimeoutHandlerMillis = readTimeoutHandlerMillis;
+    }
+
+    @Bean
+    public RestTemplateBuilder restTemplateBuilder(RestTemplateBuilderConfigurer configurer) {
+        return configurer.configure(new RestTemplateBuilder())
+                .additionalInterceptors(new RestInvokePerformanceLogger())
+                .connectTimeout(Duration.ofMillis(connectTimeoutMillis))
+                .readTimeout(Duration.ofMillis(readTimeoutHandlerMillis));
+    }
+
+    public static ResponseErrorHandler bodyPrinterWhenError(String applicationName) {
+        final Logger errorBodyLogger = LoggerFactory.getLogger("REST_INVOKE." + applicationName);
+        return new DefaultResponseErrorHandler() {
+            @Override
+            protected void handleError(@Nonnull ClientHttpResponse response, @Nonnull HttpStatusCode statusCode,
+                                       @Nullable URI url, @Nullable HttpMethod method) throws IOException {
+                try {
+                    super.handleError(response, statusCode, url, method);
+                } catch (HttpStatusCodeException ex) {
+                    errorBodyLogger.info("{} {} Returned status {} and resulted on exception {} - {}: {}",
+                            method,
+                            url,
+                            ex.getStatusCode(),
+                            ex.getClass().getSimpleName(),
+                            ex.getMessage(),
+                            ex.getResponseBodyAsString());
+                    throw ex;
+                }
+            }
+        };
+    }
+}

src/main/java/it/gov/pagopa/pu/classification/performancelogger/ApiRequestPerformanceLogger.java

@@ -0,0 +1,55 @@
+package it.gov.pagopa.pu.classification.performancelogger;
+
+import jakarta.servlet.*;
+import jakarta.servlet.http.HttpServletRequest;
+import jakarta.servlet.http.HttpServletResponse;
+import org.springframework.core.Ordered;
+import org.springframework.core.annotation.Order;
+import org.springframework.stereotype.Service;
+
+import java.io.IOException;
+import java.util.List;
+
+/**
+ * It will execute {@link PerformanceLogger} on each Api request
+ */
+@Service
+@Order(Ordered.HIGHEST_PRECEDENCE)
+public class ApiRequestPerformanceLogger implements Filter {
+
+    private static final List<String> blackListPathPrefixList = List.of(
+            "/actuator",
+            "/favicon.ico",
+            "/swagger"
+    );
+
+    @Override
+    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws ServletException, IOException {
+        if (servletRequest instanceof HttpServletRequest httpServletRequest &&
+                servletResponse instanceof HttpServletResponse httpServletResponse &&
+                isPerformanceLoggedRequest(httpServletRequest)
+        ) {
+            PerformanceLogger.execute(
+                    "API_REQUEST",
+                    getRequestDetails(httpServletRequest),
+                    () -> {
+                        filterChain.doFilter(servletRequest, servletResponse);
+                        return "ok";
+                    },
+                    x -> "HttpStatus: " + httpServletResponse.getStatus(),
+                    null);
+        } else {
+            filterChain.doFilter(servletRequest, servletResponse);
+        }
+    }
+
+    private boolean isPerformanceLoggedRequest(HttpServletRequest httpServletRequest) {
+        String requestURI = httpServletRequest.getRequestURI();
+        return blackListPathPrefixList.stream()
+                .noneMatch(requestURI::startsWith);
+    }
+
+    static String getRequestDetails(HttpServletRequest request) {
+        return "%s %s".formatted(request.getMethod(), request.getRequestURI());
+    }
+}

src/main/java/it/gov/pagopa/pu/classification/performancelogger/PerformanceLogger.java

@@ -0,0 +1,89 @@
+package it.gov.pagopa.pu.classification.performancelogger;
+
+import lombok.extern.slf4j.Slf4j;
+import org.apache.commons.lang3.ObjectUtils;
+import org.slf4j.LoggerFactory;
+import org.slf4j.event.Level;
+import org.springframework.util.function.ThrowingFunction;
+import org.springframework.util.function.ThrowingSupplier;
+
+import java.util.function.Function;
+
+/**
+ * Utility class to produce performance log
+ */
+@Slf4j
+public final class PerformanceLogger {
+    private PerformanceLogger() {
+    }
+
+    private static final PerformanceLoggerThresholdLevels defaultThresholdLevels = new PerformanceLoggerThresholdLevels(60, 300);
+
+    /**
+     * It will execute the provided logic printing the timing required to execute it.
+     *
+     * @param appenderName    The name of the appender which could be used to set logging level
+     * @param contextData     A string printed together with the performance log in order to identify it
+     * @param logic           The logic to execute and take its time
+     * @param payloadBuilder  An optional function which till take the output of the invoked logic in order to print a payload after the performance log
+     * @param thresholdLevels An optional object to configure the log level based on the logic duration (if not provided, it will use {@link #defaultThresholdLevels}
+     * @return The object returned by the monitored logic
+     */
+    public static <T> T execute(String appenderName, String contextData, ThrowingSupplier<T> logic, ThrowingFunction<T, String> payloadBuilder, PerformanceLoggerThresholdLevels thresholdLevels) {
+        long startTime = System.currentTimeMillis();
+        String payload = "";
+        try {
+            T out = logic.get();
+            payload = buildPayload(out, payloadBuilder);
+            return out;
+        } catch (Exception e) {
+            payload = "Exception %s: %s".formatted(e.getClass(), e.getMessage());
+            throw e;
+        } finally {
+            log(appenderName, contextData, startTime, payload, thresholdLevels);
+        }
+    }
+
+    private static <T> String buildPayload(T out, Function<T, String> payloadBuilder) {
+        String payload;
+        if (payloadBuilder != null) {
+            if (out != null) {
+                try {
+                    payload = payloadBuilder.apply(out);
+                } catch (Exception e) {
+                    log.warn("Something went wrong while building payload", e);
+                    payload = "Payload builder thrown Exception %s: %s".formatted(e.getClass(), e.getMessage());
+                }
+            } else {
+                payload = "Returned null";
+            }
+        } else {
+            payload = "";
+        }
+        return payload;
+    }
+
+    public static void log(String appenderName, String contextData, long startTime, String payload, PerformanceLoggerThresholdLevels thresholdLevels) {
+        long durationMillis = System.currentTimeMillis() - startTime;
+        Level level = resolveLevel(durationMillis, thresholdLevels);
+        LoggerFactory.getLogger("PERFORMANCE_LOG." + appenderName)
+                .atLevel(level)
+                .log(
+                        "{}Time occurred to perform business logic: {} ms. {}",
+                        contextData != null ? "[" + contextData + "] " : "",
+                        durationMillis,
+                        payload);
+    }
+
+    static Level resolveLevel(long durationMillis, PerformanceLoggerThresholdLevels thresholdLevels) {
+        long durationSeconds = durationMillis / 1000;
+        thresholdLevels = ObjectUtils.firstNonNull(thresholdLevels, defaultThresholdLevels);
+        if (durationSeconds < thresholdLevels.getWarn()) {
+            return Level.INFO;
+        } else if (durationSeconds < thresholdLevels.getError()) {
+            return Level.WARN;
+        } else {
+            return Level.ERROR;
+        }
+    }
+}

src/main/java/it/gov/pagopa/pu/classification/performancelogger/PerformanceLoggerThresholdLevels.java

@@ -0,0 +1,15 @@
+package it.gov.pagopa.pu.classification.performancelogger;
+
+import lombok.AllArgsConstructor;
+import lombok.Data;
+import lombok.NoArgsConstructor;
+
+@Data
+@NoArgsConstructor
+@AllArgsConstructor
+public class PerformanceLoggerThresholdLevels {
+    /** Number of seconds from which the log will be printed as a WARN */
+    private long warn;
+    /** Number of seconds from which the log will be printed as an ERROR */
+    private long error;
+}

src/main/java/it/gov/pagopa/pu/classification/performancelogger/RestInvokePerformanceLogger.java

@@ -0,0 +1,28 @@
+package it.gov.pagopa.pu.classification.performancelogger;
+
+import jakarta.annotation.Nonnull;
+import org.springframework.http.HttpRequest;
+import org.springframework.http.client.ClientHttpRequestExecution;
+import org.springframework.http.client.ClientHttpRequestInterceptor;
+import org.springframework.http.client.ClientHttpResponse;
+
+/**
+ * It will execute {@link PerformanceLogger} on each RestTemplate invocation
+ */
+public class RestInvokePerformanceLogger implements ClientHttpRequestInterceptor {
+
+    @Override
+    @Nonnull
+    public ClientHttpResponse intercept(@Nonnull HttpRequest request, @Nonnull byte[] body, @Nonnull ClientHttpRequestExecution execution) {
+        return PerformanceLogger.execute(
+                "REST_INVOKE",
+                getRequestDetails(request),
+                () -> execution.execute(request, body),
+                x -> "HttpStatus: " + x.getStatusCode().value(),
+                null);
+    }
+
+    static String getRequestDetails(HttpRequest request) {
+        return "%s %s".formatted(request.getMethod(), request.getURI());
+    }
+}