http://jira.mfd.msk:8088/browse/BKI-3215 Log http requests; Log slow mapper calls; Added spring AOP

This commit is contained in:
Mikhail Trofimov 2025-09-30 14:15:33 +03:00
parent f888f9af4c
commit 98622d7817
4 changed files with 215 additions and 60 deletions

139
pom.xml
View file

@ -27,6 +27,10 @@
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>
<dependency>
<groupId>org.mybatis.spring.boot</groupId>
<artifactId>mybatis-spring-boot-starter</artifactId>
@ -122,8 +126,83 @@
<version>3.0.4</version>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.mockito</groupId>
<artifactId>mockito-junit-jupiter</artifactId>
<scope>test</scope>
</dependency>
</dependencies>
<profiles>
<profile>
<id>docker-push-dev</id>
<build>
<pluginManagement>
<plugins>
<plugin>
<groupId>io.fabric8</groupId>
<artifactId>docker-maven-plugin</artifactId>
<version>0.45.0</version>
<executions>
<execution>
<id>Build and deploy docker container</id>
<phase>install</phase>
<goals>
<!--<goal>build</goal>-->
<goal>push</goal>
</goals>
</execution>
</executions>
<configuration>
<images>
<image>
<name>${project.artifactId}:${project.version}</name>
<registry>${registry.url}</registry>
<build>
<dockerFile>${project.basedir}/Dockerfile</dockerFile>
<assembly>
<inline>
<files>
<file>
<source>${project.build.directory}/${project.build.finalName}.jar</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/apm-agent/elastic-apm-agent-1.45.0.jar</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/start-credit-tracker.sh</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/credit-tracker.properties</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/monitoring-request.xsd</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/signal-package.xsd</source>
<outputDirectory>.</outputDirectory>
</file>
</files>
</inline>
</assembly>
<tags>
<tag>${project.version}</tag>
</tags>
</build>
</image>
</images>
</configuration>
</plugin>
</plugins>
</pluginManagement>
</build>
</profile>
</profiles>
<build>
<finalName>credit-tracker</finalName>
<plugins>
@ -181,65 +260,7 @@
</includeOnlyProperties>
</configuration>
</plugin>
<plugin>
<groupId>io.fabric8</groupId>
<artifactId>docker-maven-plugin</artifactId>
<version>0.45.0</version>
<executions>
<execution>
<id>Build and deploy docker container</id>
<phase>install</phase>
<goals>
<goal>build</goal>
<goal>push</goal>
</goals>
</execution>
</executions>
<configuration>
<images>
<image>
<name>${project.artifactId}:${project.version}</name>
<registry>${registry.url}</registry>
<build>
<dockerFile>${project.basedir}/Dockerfile</dockerFile>
<assembly>
<inline>
<files>
<file>
<source>${project.build.directory}/${project.build.finalName}.jar</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/apm-agent/elastic-apm-agent-1.45.0.jar</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/start-credit-tracker.sh</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/credit-tracker.properties</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/monitoring-request.xsd</source>
<outputDirectory>.</outputDirectory>
</file>
<file>
<source>${project.basedir}/signal-package.xsd</source>
<outputDirectory>.</outputDirectory>
</file>
</files>
</inline>
</assembly>
<tags>
<tag>${project.version}</tag>
</tags>
</build>
</image>
</images>
</configuration>
</plugin>
</plugins>
</build>

View file

@ -0,0 +1,28 @@
package ru.nbch.credit_tracker.component;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;
@Aspect
@Slf4j
@Component
public class MapperTimingAspect {
@Around("within(@org.apache.ibatis.annotations.Mapper *)")
public Object timeMapper(ProceedingJoinPoint pjp) throws Throwable {
long start = System.nanoTime();
try {
return pjp.proceed();
} finally {
long tookMs = (System.nanoTime() - start) / 1_000_000;
String method = pjp.getSignature().toShortString();
if (tookMs > 200) {
log.warn("Slow mapper call {} took {} ms", method, tookMs);
} else {
log.debug("Mapper call {} took {} ms", method, tookMs);
}
}
}
}

View file

@ -0,0 +1,106 @@
package ru.nbch.credit_tracker.config.rest.filters;
import jakarta.servlet.FilterChain;
import jakarta.servlet.ServletException;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import lombok.extern.slf4j.Slf4j;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import org.springframework.util.StringUtils;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;
import org.springframework.web.util.ContentCachingResponseWrapper;
import java.io.IOException;
import java.nio.charset.StandardCharsets;
import java.util.*;
import java.util.stream.Collectors;
@Component
@Slf4j
@Order(0)
public class HttpLoggingFilter extends OncePerRequestFilter {
private static final Set<String> SENSITIVE_HEADERS = Set.of("authorization", "cookie", "set-cookie");
private static final int MAX_BODY = 10 * 1024;
@Override
protected boolean shouldNotFilter(HttpServletRequest request) {
String path = request.getRequestURI();
return path.startsWith("/actuator/health") || path.startsWith("/swagger")
|| path.startsWith("/v3/api-docs") || path.startsWith("/static/");
}
@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain chain)
throws ServletException, IOException {
long startNs = System.nanoTime();
ContentCachingRequestWrapper req = wrapRequest(request);
ContentCachingResponseWrapper resp = new ContentCachingResponseWrapper(response);
String correlationId = Optional.ofNullable(request.getHeader("X-Correlation-Id"))
.filter(StringUtils::hasText)
.orElse(UUID.randomUUID().toString());
resp.setHeader("X-Correlation-Id", correlationId);
try {
chain.doFilter(req, resp);
} finally {
long tookMs = (System.nanoTime() - startNs) / 1_000_000;
String requestBody = readBody(req.getContentAsByteArray(), req.getCharacterEncoding());
String responseBody = readBody(resp.getContentAsByteArray(), resp.getCharacterEncoding());
Map<String, String> reqHeaders = headersMap(req);
Map<String, String> respHeaders = headersMap(resp);
mask(reqHeaders);
mask(respHeaders);
log.info(
"HTTP {} {}{} | status={} | took={}ms | cid={} | reqHeaders={} | reqBody={} | respHeaders={} | respBody={}",
req.getMethod(),
req.getRequestURI(),
req.getQueryString() == null ? "" : "?" + req.getQueryString(),
resp.getStatus(),
tookMs,
correlationId,
reqHeaders,
requestBody,
respHeaders,
responseBody
);
resp.copyBodyToResponse();
}
}
private static ContentCachingRequestWrapper wrapRequest(HttpServletRequest request) {
return (request instanceof ContentCachingRequestWrapper c) ? c : new ContentCachingRequestWrapper(request, MAX_BODY);
}
private static String readBody(byte[] buf, String encoding) {
if (buf == null || buf.length == 0) return "";
var bytes = buf.length > MAX_BODY ? Arrays.copyOf(buf, MAX_BODY) : buf;
String body = new String(bytes, encoding != null ? java.nio.charset.Charset.forName(encoding) : StandardCharsets.UTF_8);
if (buf.length > MAX_BODY) body += "…[truncated]";
return body;
}
private static Map<String, String> headersMap(HttpServletRequest req) {
return Collections.list(req.getHeaderNames()).stream()
.collect(Collectors.toMap(h -> h, req::getHeader, (a, b) -> a, LinkedHashMap::new));
}
private static Map<String, String> headersMap(HttpServletResponse resp) {
return resp.getHeaderNames().stream()
.collect(Collectors.toMap(h -> h, resp::getHeader, (a, b) -> a, LinkedHashMap::new));
}
private static void mask(Map<String, String> headers) {
headers.replaceAll((k, v) -> SENSITIVE_HEADERS.contains(k.toLowerCase()) ? "***" : v);
}
}

View file

@ -8,7 +8,7 @@
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
<charset>utf-8</charset>
</encoder>
</appender>