From 98622d78177411db0e66384e2c53a4cc4c257fc8 Mon Sep 17 00:00:00 2001 From: Mikhail Trofimov Date: Tue, 30 Sep 2025 14:15:33 +0300 Subject: [PATCH] http://jira.mfd.msk:8088/browse/BKI-3215 Log http requests; Log slow mapper calls; Added spring AOP --- pom.xml | 139 ++++++++++-------- .../component/MapperTimingAspect.java | 28 ++++ .../rest/filters/HttpLoggingFilter.java | 106 +++++++++++++ src/main/resources/logback.xml | 2 +- 4 files changed, 215 insertions(+), 60 deletions(-) create mode 100644 src/main/java/ru/nbch/credit_tracker/component/MapperTimingAspect.java create mode 100644 src/main/java/ru/nbch/credit_tracker/config/rest/filters/HttpLoggingFilter.java diff --git a/pom.xml b/pom.xml index f876eb6..ffd17aa 100644 --- a/pom.xml +++ b/pom.xml @@ -27,6 +27,10 @@ org.springframework.boot spring-boot-starter-web + + org.springframework.boot + spring-boot-starter-aop + org.mybatis.spring.boot mybatis-spring-boot-starter @@ -122,8 +126,83 @@ 3.0.4 test + + org.mockito + mockito-junit-jupiter + test + + + + docker-push-dev + + + + + io.fabric8 + docker-maven-plugin + 0.45.0 + + + Build and deploy docker container + install + + + push + + + + + + + ${project.artifactId}:${project.version} + ${registry.url} + + ${project.basedir}/Dockerfile + + + + + ${project.build.directory}/${project.build.finalName}.jar + . + + + ${project.basedir}/apm-agent/elastic-apm-agent-1.45.0.jar + . + + + ${project.basedir}/start-credit-tracker.sh + . + + + ${project.basedir}/credit-tracker.properties + . + + + ${project.basedir}/monitoring-request.xsd + . + + + ${project.basedir}/signal-package.xsd + . + + + + + + ${project.version} + + + + + + + + + + + credit-tracker @@ -181,65 +260,7 @@ - - io.fabric8 - docker-maven-plugin - 0.45.0 - - - Build and deploy docker container - install - - build - push - - - - - - - ${project.artifactId}:${project.version} - ${registry.url} - - ${project.basedir}/Dockerfile - - - - - ${project.build.directory}/${project.build.finalName}.jar - . - - - ${project.basedir}/apm-agent/elastic-apm-agent-1.45.0.jar - . - - - ${project.basedir}/start-credit-tracker.sh - . - - - ${project.basedir}/credit-tracker.properties - . - - - ${project.basedir}/monitoring-request.xsd - . - - - ${project.basedir}/signal-package.xsd - . - - - - - - ${project.version} - - - - - - + diff --git a/src/main/java/ru/nbch/credit_tracker/component/MapperTimingAspect.java b/src/main/java/ru/nbch/credit_tracker/component/MapperTimingAspect.java new file mode 100644 index 0000000..7802484 --- /dev/null +++ b/src/main/java/ru/nbch/credit_tracker/component/MapperTimingAspect.java @@ -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); + } + } + } +} diff --git a/src/main/java/ru/nbch/credit_tracker/config/rest/filters/HttpLoggingFilter.java b/src/main/java/ru/nbch/credit_tracker/config/rest/filters/HttpLoggingFilter.java new file mode 100644 index 0000000..262a9d2 --- /dev/null +++ b/src/main/java/ru/nbch/credit_tracker/config/rest/filters/HttpLoggingFilter.java @@ -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 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 reqHeaders = headersMap(req); + Map 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 headersMap(HttpServletRequest req) { + return Collections.list(req.getHeaderNames()).stream() + .collect(Collectors.toMap(h -> h, req::getHeader, (a, b) -> a, LinkedHashMap::new)); + } + + private static Map headersMap(HttpServletResponse resp) { + return resp.getHeaderNames().stream() + .collect(Collectors.toMap(h -> h, resp::getHeader, (a, b) -> a, LinkedHashMap::new)); + } + + private static void mask(Map headers) { + headers.replaceAll((k, v) -> SENSITIVE_HEADERS.contains(k.toLowerCase()) ? "***" : v); + } +} diff --git a/src/main/resources/logback.xml b/src/main/resources/logback.xml index 0825d76..88ce91c 100644 --- a/src/main/resources/logback.xml +++ b/src/main/resources/logback.xml @@ -8,7 +8,7 @@ - %d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n + %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n utf-8