feat: Performance logging

build.gradle.kts

@@ -58,6 +58,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/template/config/RestTemplateConfig.java

@@ -0,0 +1,67 @@
+package it.gov.pagopa.template.config;
+
+import it.gov.pagopa.template.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/template/performancelogger/ApiRequestPerformanceLogger.java

@@ -0,0 +1,55 @@
+package it.gov.pagopa.template.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/template/performancelogger/PerformanceLogger.java

@@ -0,0 +1,89 @@
+package it.gov.pagopa.template.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/template/performancelogger/PerformanceLoggerThresholdLevels.java

@@ -0,0 +1,15 @@
+package it.gov.pagopa.template.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/template/performancelogger/RestInvokePerformanceLogger.java

@@ -0,0 +1,28 @@
+package it.gov.pagopa.template.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());
+    }
+}

src/main/resources/application.yml

@@ -2,46 +2,56 @@ server:
   http: "${SERVER_PORT:8080}"
 
 spring:
-    application:
-        name: ${artifactId}
-        version: ${version}
-    jmx.enabled: true
-    threads:
-      virtual:
-        enabled: true
+  application:
+    name: ${artifactId}
+    version: ${version}
+  jmx.enabled: true
+  threads:
+    virtual:
+      enabled: true
 management:
-    endpoints:
-      web:
-        exposure:
-          include: health, info, prometheus, metrics
-        base-path: /actuator
-    endpoint:
-      health:
-        probes.enabled: true
-        logging.slow-indicator-threshold: "\${HEALTH_ACTUATOR_LOGGER_TIMEOUT_DURATION:PT1S}"
-        group:
-          readiness.include: "*"
-          liveness.include: livenessState,diskSpace,ping
+  endpoints:
+    web:
+      exposure:
+        include: health, info, prometheus, metrics
+      base-path: /actuator
+  endpoint:
+    health:
+      probes.enabled: true
+      logging.slow-indicator-threshold: "\${HEALTH_ACTUATOR_LOGGER_TIMEOUT_DURATION:PT1S}"
+      group:
+        readiness.include: "*"
+        liveness.include: livenessState,diskSpace,ping
+    prometheus:
+      enabled: true
+  metrics:
+    tags:
+      application: ${artifactId}
+    export:
       prometheus:
         enabled: true
-    metrics:
-      tags:
-        application: ${artifactId}
-      export:
-        prometheus:
-          enabled: true
-          step: 1m
-          descriptions: true
-      enable:
-        jvm: true
-        process: true
-        system: true
-        http: true
-        logback: true
+        step: 1m
+        descriptions: true
+    enable:
+      jvm: true
+      process: true
+      system: true
+      http: true
+      logback: true
 
 logging:
   level:
     root: "\${LOG_LEVEL_ROOT:INFO}"
     it.gov.pagopa: "\${LOG_LEVEL_PAGOPA:INFO}"
     org.springframework: "\${LOG_LEVEL_SPRING:INFO}"
     org.springframework.boot.availability: "\${LOG_LEVEL_SPRING_BOOT_AVAILABILITY:DEBUG}"
+    it.gov.pagopa.template.exception.ControllerExceptionHandler: "\${LOGGING_LEVEL_API_REQUEST_EXCEPTION:INFO}"
+    org.springdoc.core.utils.SpringDocAnnotationsUtils: "\${LOG_LEVEL_SPRING_DOC:ERROR}"
+    PERFORMANCE_LOG: "\${LOG_LEVEL_PERFORMANCE_LOG:INFO}"
+    PERFORMANCE_LOG.API_REQUEST: "\${LOG_LEVEL_PERFORMANCE_LOG_API_REQUEST:\${logging.level.PERFORMANCE_LOG}}"
+    PERFORMANCE_LOG.REST_INVOKE: "\${LOG_LEVEL_PERFORMANCE_LOG_REST_INVOKE:\${logging.level.PERFORMANCE_LOG}}"
+
+rest:
+  default-timeout:
+    connect-millis: "\${DEFAULT_REST_CONNECT_TIMEOUT_MILLIS:120000}"
+    read-millis: "\${DEFAULT_REST_READ_TIMEOUT_MILLIS:120000}"