Skip to content

Commit 47ab6de

Browse files
antonioT90antonioT90
authored
feat: Performance logging (#19)
1 parent 0318f22 commit 47ab6de

File tree

11 files changed

+651
-33
lines changed

11 files changed

+651
-33
lines changed

‎build.gradle.kts‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -58,6 +58,16 @@ tasks.withType<Test> {
5858
finalizedBy(tasks.jacocoTestReport)
5959
}
6060

61+
val mockitoAgent = configurations.create("mockitoAgent")
62+
dependencies {
63+
mockitoAgent("org.mockito:mockito-core") { isTransitive = false }
64+
}
65+
tasks {
66+
test {
67+
jvmArgs("-javaagent:${mockitoAgent.asPath}")
68+
}
69+
}
70+
6171
tasks.jacocoTestReport {
6272
dependsOn(tasks.test)
6373
reports {

‎src/main/java/it/gov/pagopa/template/config/RestTemplateConfig.java‎

Lines changed: 67 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,67 @@
1+
package it.gov.pagopa.template.config;
2+
3+
import it.gov.pagopa.template.performancelogger.RestInvokePerformanceLogger;
4+
import jakarta.annotation.Nonnull;
5+
import lombok.extern.slf4j.Slf4j;
6+
import org.slf4j.Logger;
7+
import org.slf4j.LoggerFactory;
8+
import org.springframework.beans.factory.annotation.Value;
9+
import org.springframework.boot.autoconfigure.web.client.RestTemplateBuilderConfigurer;
10+
import org.springframework.boot.web.client.RestTemplateBuilder;
11+
import org.springframework.context.annotation.Bean;
12+
import org.springframework.context.annotation.Configuration;
13+
import org.springframework.http.HttpMethod;
14+
import org.springframework.http.HttpStatusCode;
15+
import org.springframework.http.client.ClientHttpResponse;
16+
import org.springframework.lang.Nullable;
17+
import org.springframework.web.client.DefaultResponseErrorHandler;
18+
import org.springframework.web.client.HttpStatusCodeException;
19+
import org.springframework.web.client.ResponseErrorHandler;
20+
21+
import java.io.IOException;
22+
import java.net.URI;
23+
import java.time.Duration;
24+
25+
@Slf4j
26+
@Configuration(proxyBeanMethods = false)
27+
public class RestTemplateConfig {
28+
private final int connectTimeoutMillis;
29+
private final int readTimeoutHandlerMillis;
30+
31+
public RestTemplateConfig(
32+
@Value("${rest.default-timeout.connect-millis}") int connectTimeoutMillis,
33+
@Value("${rest.default-timeout.read-millis}") int readTimeoutHandlerMillis) {
34+
this.connectTimeoutMillis = connectTimeoutMillis;
35+
this.readTimeoutHandlerMillis = readTimeoutHandlerMillis;
36+
}
37+
38+
@Bean
39+
public RestTemplateBuilder restTemplateBuilder(RestTemplateBuilderConfigurer configurer) {
40+
return configurer.configure(new RestTemplateBuilder())
41+
.additionalInterceptors(new RestInvokePerformanceLogger())
42+
.connectTimeout(Duration.ofMillis(connectTimeoutMillis))
43+
.readTimeout(Duration.ofMillis(readTimeoutHandlerMillis));
44+
}
45+
46+
public static ResponseErrorHandler bodyPrinterWhenError(String applicationName) {
47+
final Logger errorBodyLogger = LoggerFactory.getLogger("REST_INVOKE." + applicationName);
48+
return new DefaultResponseErrorHandler() {
49+
@Override
50+
protected void handleError(@Nonnull ClientHttpResponse response, @Nonnull HttpStatusCode statusCode,
51+
@Nullable URI url, @Nullable HttpMethod method) throws IOException {
52+
try {
53+
super.handleError(response, statusCode, url, method);
54+
} catch (HttpStatusCodeException ex) {
55+
errorBodyLogger.info("{} {} Returned status {} and resulted on exception {} - {}: {}",
56+
method,
57+
url,
58+
ex.getStatusCode(),
59+
ex.getClass().getSimpleName(),
60+
ex.getMessage(),
61+
ex.getResponseBodyAsString());
62+
throw ex;
63+
}
64+
}
65+
};
66+
}
67+
}

‎src/main/java/it/gov/pagopa/template/performancelogger/ApiRequestPerformanceLogger.java‎

Lines changed: 55 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,55 @@
1+
package it.gov.pagopa.template.performancelogger;
2+
3+
import jakarta.servlet.*;
4+
import jakarta.servlet.http.HttpServletRequest;
5+
import jakarta.servlet.http.HttpServletResponse;
6+
import org.springframework.core.Ordered;
7+
import org.springframework.core.annotation.Order;
8+
import org.springframework.stereotype.Service;
9+
10+
import java.io.IOException;
11+
import java.util.List;
12+
13+
/**
14+
* It will execute {@link PerformanceLogger} on each Api request
15+
*/
16+
@Service
17+
@Order(Ordered.HIGHEST_PRECEDENCE)
18+
public class ApiRequestPerformanceLogger implements Filter {
19+
20+
private static final List<String> blackListPathPrefixList = List.of(
21+
"/actuator",
22+
"/favicon.ico",
23+
"/swagger"
24+
);
25+
26+
@Override
27+
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws ServletException, IOException {
28+
if (servletRequest instanceof HttpServletRequest httpServletRequest &&
29+
servletResponse instanceof HttpServletResponse httpServletResponse &&
30+
isPerformanceLoggedRequest(httpServletRequest)
31+
) {
32+
PerformanceLogger.execute(
33+
"API_REQUEST",
34+
getRequestDetails(httpServletRequest),
35+
() -> {
36+
filterChain.doFilter(servletRequest, servletResponse);
37+
return "ok";
38+
},
39+
x -> "HttpStatus: " + httpServletResponse.getStatus(),
40+
null);
41+
} else {
42+
filterChain.doFilter(servletRequest, servletResponse);
43+
}
44+
}
45+
46+
private boolean isPerformanceLoggedRequest(HttpServletRequest httpServletRequest) {
47+
String requestURI = httpServletRequest.getRequestURI();
48+
return blackListPathPrefixList.stream()
49+
.noneMatch(requestURI::startsWith);
50+
}
51+
52+
static String getRequestDetails(HttpServletRequest request) {
53+
return "%s %s".formatted(request.getMethod(), request.getRequestURI());
54+
}
55+
}

‎src/main/java/it/gov/pagopa/template/performancelogger/PerformanceLogger.java‎

Lines changed: 89 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,89 @@
1+
package it.gov.pagopa.template.performancelogger;
2+
3+
import lombok.extern.slf4j.Slf4j;
4+
import org.apache.commons.lang3.ObjectUtils;
5+
import org.slf4j.LoggerFactory;
6+
import org.slf4j.event.Level;
7+
import org.springframework.util.function.ThrowingFunction;
8+
import org.springframework.util.function.ThrowingSupplier;
9+
10+
import java.util.function.Function;
11+
12+
/**
13+
* Utility class to produce performance log
14+
*/
15+
@Slf4j
16+
public final class PerformanceLogger {
17+
private PerformanceLogger() {
18+
}
19+
20+
private static final PerformanceLoggerThresholdLevels defaultThresholdLevels = new PerformanceLoggerThresholdLevels(60, 300);
21+
22+
/**
23+
* It will execute the provided logic printing the timing required to execute it.
24+
*
25+
* @param appenderName The name of the appender which could be used to set logging level
26+
* @param contextData A string printed together with the performance log in order to identify it
27+
* @param logic The logic to execute and take its time
28+
* @param payloadBuilder An optional function which till take the output of the invoked logic in order to print a payload after the performance log
29+
* @param thresholdLevels An optional object to configure the log level based on the logic duration (if not provided, it will use {@link #defaultThresholdLevels}
30+
* @return The object returned by the monitored logic
31+
*/
32+
public static <T> T execute(String appenderName, String contextData, ThrowingSupplier<T> logic, ThrowingFunction<T, String> payloadBuilder, PerformanceLoggerThresholdLevels thresholdLevels) {
33+
long startTime = System.currentTimeMillis();
34+
String payload = "";
35+
try {
36+
T out = logic.get();
37+
payload = buildPayload(out, payloadBuilder);
38+
return out;
39+
} catch (Exception e) {
40+
payload = "Exception %s: %s".formatted(e.getClass(), e.getMessage());
41+
throw e;
42+
} finally {
43+
log(appenderName, contextData, startTime, payload, thresholdLevels);
44+
}
45+
}
46+
47+
private static <T> String buildPayload(T out, Function<T, String> payloadBuilder) {
48+
String payload;
49+
if (payloadBuilder != null) {
50+
if (out != null) {
51+
try {
52+
payload = payloadBuilder.apply(out);
53+
} catch (Exception e) {
54+
log.warn("Something went wrong while building payload", e);
55+
payload = "Payload builder thrown Exception %s: %s".formatted(e.getClass(), e.getMessage());
56+
}
57+
} else {
58+
payload = "Returned null";
59+
}
60+
} else {
61+
payload = "";
62+
}
63+
return payload;
64+
}
65+
66+
public static void log(String appenderName, String contextData, long startTime, String payload, PerformanceLoggerThresholdLevels thresholdLevels) {
67+
long durationMillis = System.currentTimeMillis() - startTime;
68+
Level level = resolveLevel(durationMillis, thresholdLevels);
69+
LoggerFactory.getLogger("PERFORMANCE_LOG." + appenderName)
70+
.atLevel(level)
71+
.log(
72+
"{}Time occurred to perform business logic: {} ms. {}",
73+
contextData != null ? "[" + contextData + "] " : "",
74+
durationMillis,
75+
payload);
76+
}
77+
78+
static Level resolveLevel(long durationMillis, PerformanceLoggerThresholdLevels thresholdLevels) {
79+
long durationSeconds = durationMillis / 1000;
80+
thresholdLevels = ObjectUtils.firstNonNull(thresholdLevels, defaultThresholdLevels);
81+
if (durationSeconds < thresholdLevels.getWarn()) {
82+
return Level.INFO;
83+
} else if (durationSeconds < thresholdLevels.getError()) {
84+
return Level.WARN;
85+
} else {
86+
return Level.ERROR;
87+
}
88+
}
89+
}

‎src/main/java/it/gov/pagopa/template/performancelogger/PerformanceLoggerThresholdLevels.java‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
package it.gov.pagopa.template.performancelogger;
2+
3+
import lombok.AllArgsConstructor;
4+
import lombok.Data;
5+
import lombok.NoArgsConstructor;
6+
7+
@Data
8+
@NoArgsConstructor
9+
@AllArgsConstructor
10+
public class PerformanceLoggerThresholdLevels {
11+
/** Number of seconds from which the log will be printed as a WARN */
12+
private long warn;
13+
/** Number of seconds from which the log will be printed as an ERROR */
14+
private long error;
15+
}

‎src/main/java/it/gov/pagopa/template/performancelogger/RestInvokePerformanceLogger.java‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,28 @@
1+
package it.gov.pagopa.template.performancelogger;
2+
3+
import jakarta.annotation.Nonnull;
4+
import org.springframework.http.HttpRequest;
5+
import org.springframework.http.client.ClientHttpRequestExecution;
6+
import org.springframework.http.client.ClientHttpRequestInterceptor;
7+
import org.springframework.http.client.ClientHttpResponse;
8+
9+
/**
10+
* It will execute {@link PerformanceLogger} on each RestTemplate invocation
11+
*/
12+
public class RestInvokePerformanceLogger implements ClientHttpRequestInterceptor {
13+
14+
@Override
15+
@Nonnull
16+
public ClientHttpResponse intercept(@Nonnull HttpRequest request, @Nonnull byte[] body, @Nonnull ClientHttpRequestExecution execution) {
17+
return PerformanceLogger.execute(
18+
"REST_INVOKE",
19+
getRequestDetails(request),
20+
() -> execution.execute(request, body),
21+
x -> "HttpStatus: " + x.getStatusCode().value(),
22+
null);
23+
}
24+
25+
static String getRequestDetails(HttpRequest request) {
26+
return "%s %s".formatted(request.getMethod(), request.getURI());
27+
}
28+
}

‎src/main/resources/application.yml‎

Lines changed: 43 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -2,46 +2,56 @@ server:
22
http: "${SERVER_PORT:8080}"
33

44
spring:
5-
application:
6-
name: ${artifactId}
7-
version: ${version}
8-
jmx.enabled: true
9-
threads:
10-
virtual:
11-
enabled: true
5+
application:
6+
name: ${artifactId}
7+
version: ${version}
8+
jmx.enabled: true
9+
threads:
10+
virtual:
11+
enabled: true
1212
management:
13-
endpoints:
14-
web:
15-
exposure:
16-
include: health, info, prometheus, metrics
17-
base-path: /actuator
18-
endpoint:
19-
health:
20-
probes.enabled: true
21-
logging.slow-indicator-threshold: "\${HEALTH_ACTUATOR_LOGGER_TIMEOUT_DURATION:PT1S}"
22-
group:
23-
readiness.include: "*"
24-
liveness.include: livenessState,diskSpace,ping
13+
endpoints:
14+
web:
15+
exposure:
16+
include: health, info, prometheus, metrics
17+
base-path: /actuator
18+
endpoint:
19+
health:
20+
probes.enabled: true
21+
logging.slow-indicator-threshold: "\${HEALTH_ACTUATOR_LOGGER_TIMEOUT_DURATION:PT1S}"
22+
group:
23+
readiness.include: "*"
24+
liveness.include: livenessState,diskSpace,ping
25+
prometheus:
26+
enabled: true
27+
metrics:
28+
tags:
29+
application: ${artifactId}
30+
export:
2531
prometheus:
2632
enabled: true
27-
metrics:
28-
tags:
29-
application: ${artifactId}
30-
export:
31-
prometheus:
32-
enabled: true
33-
step: 1m
34-
descriptions: true
35-
enable:
36-
jvm: true
37-
process: true
38-
system: true
39-
http: true
40-
logback: true
33+
step: 1m
34+
descriptions: true
35+
enable:
36+
jvm: true
37+
process: true
38+
system: true
39+
http: true
40+
logback: true
4141

4242
logging:
4343
level:
4444
root: "\${LOG_LEVEL_ROOT:INFO}"
4545
it.gov.pagopa: "\${LOG_LEVEL_PAGOPA:INFO}"
4646
org.springframework: "\${LOG_LEVEL_SPRING:INFO}"
4747
org.springframework.boot.availability: "\${LOG_LEVEL_SPRING_BOOT_AVAILABILITY:DEBUG}"
48+
it.gov.pagopa.template.exception.ControllerExceptionHandler: "\${LOGGING_LEVEL_API_REQUEST_EXCEPTION:INFO}"
49+
org.springdoc.core.utils.SpringDocAnnotationsUtils: "\${LOG_LEVEL_SPRING_DOC:ERROR}"
50+
PERFORMANCE_LOG: "\${LOG_LEVEL_PERFORMANCE_LOG:INFO}"
51+
PERFORMANCE_LOG.API_REQUEST: "\${LOG_LEVEL_PERFORMANCE_LOG_API_REQUEST:\${logging.level.PERFORMANCE_LOG}}"
52+
PERFORMANCE_LOG.REST_INVOKE: "\${LOG_LEVEL_PERFORMANCE_LOG_REST_INVOKE:\${logging.level.PERFORMANCE_LOG}}"
53+
54+
rest:
55+
default-timeout:
56+
connect-millis: "\${DEFAULT_REST_CONNECT_TIMEOUT_MILLIS:120000}"
57+
read-millis: "\${DEFAULT_REST_READ_TIMEOUT_MILLIS:120000}"

0 commit comments

Comments
 (0)