From 734ff2e07c221da0b9d46751c1152039b05c9e6c Mon Sep 17 00:00:00 2001 From: lobo Date: Sun, 11 Oct 2026 11:05:18 +0200 Subject: [PATCH] feat(configuration): add request timing log One INFO line per API request: method, handler pattern, status, ms. No ids or query strings in the line. Refs #40. --- readme.md | 7 ++ .../configuration/RequestTimingFilter.java | 54 ++++++++++++ .../RequestTimingFilterTest.java | 83 +++++++++++++++++++ 3 files changed, 144 insertions(+) create mode 100644 src/main/java/auth_service/configuration/RequestTimingFilter.java create mode 100644 src/test/java/auth_service/configuration/RequestTimingFilterTest.java diff --git a/readme.md b/readme.md index 698b4fe..c10c79a 100644 --- a/readme.md +++ b/readme.md @@ -477,6 +477,13 @@ openssl pkey -in private.pem -outform DER | base64 -w0 # JWT_PRIVATE_KEY openssl pkey -in private.pem -pubout -outform DER | base64 -w0 # JWT_PUBLIC_KEY ``` +### Request timing log + +`RequestTimingFilter` writes one INFO line to stdout per API request: method, handler path pattern, status and +duration, e.g. `GET /api/users/me 200 12 ms`. The pattern is `-` when no handler matched (e.g. a `401` before +routing). The line never holds ids, query strings, user data or tokens. `/actuator/**` is skipped. An exception +that leaves the filter chain is logged as `500`. + ## Tests ```bash diff --git a/src/main/java/auth_service/configuration/RequestTimingFilter.java b/src/main/java/auth_service/configuration/RequestTimingFilter.java new file mode 100644 index 0000000..e3692ca --- /dev/null +++ b/src/main/java/auth_service/configuration/RequestTimingFilter.java @@ -0,0 +1,54 @@ +package auth_service.configuration; + +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import org.jspecify.annotations.NonNull; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.springframework.core.Ordered; +import org.springframework.core.annotation.Order; +import org.springframework.stereotype.Component; +import org.springframework.web.filter.OncePerRequestFilter; +import org.springframework.web.servlet.HandlerMapping; + +import java.io.IOException; + +/** + * One INFO line per request: method, handler pattern, status, duration. The pattern (e.g. {@code /api/games/{appid}}) + * stands for the path, so the line holds no ids, query, user or credentials. A request no handler took shows {@code -}. + */ +@Component +@Order(Ordered.HIGHEST_PRECEDENCE) +public class RequestTimingFilter extends OncePerRequestFilter { + + private static final Logger LOG = LoggerFactory.getLogger(RequestTimingFilter.class); + + @Override + protected void doFilterInternal( + @NonNull HttpServletRequest request, + @NonNull HttpServletResponse response, + @NonNull FilterChain filterChain + ) throws ServletException, IOException { + long start = System.nanoTime(); + int status = HttpServletResponse.SC_INTERNAL_SERVER_ERROR; + try { + filterChain.doFilter(request, response); + status = response.getStatus(); + } finally { + // An exception that leaves the chain ends as a 500; the container sets it only after this filter. + Object pattern = request.getAttribute(HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE); + LOG.info("{} {} {} {} ms", request.getMethod(), pattern != null ? pattern : "-", status, + (System.nanoTime() - start) / 1_000_000); + } + } + + /** + * The health check calls the actuator every 30 s; its lines would flood the log. + */ + @Override + protected boolean shouldNotFilter(@NonNull HttpServletRequest request) { + return request.getRequestURI().startsWith("/actuator/"); + } +} diff --git a/src/test/java/auth_service/configuration/RequestTimingFilterTest.java b/src/test/java/auth_service/configuration/RequestTimingFilterTest.java new file mode 100644 index 0000000..511b5a0 --- /dev/null +++ b/src/test/java/auth_service/configuration/RequestTimingFilterTest.java @@ -0,0 +1,83 @@ +package auth_service.configuration; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import jakarta.servlet.ServletRequest; +import jakarta.servlet.ServletResponse; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.springframework.mock.web.MockFilterChain; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.mock.web.MockHttpServletResponse; +import org.springframework.web.servlet.HandlerMapping; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; + +class RequestTimingFilterTest { + + private final Logger logger = (Logger) LoggerFactory.getLogger(RequestTimingFilter.class); + private final ListAppender lines = new ListAppender<>(); + + @BeforeEach + void capture() { + lines.start(); + logger.addAppender(lines); + } + + @AfterEach + void release() { + logger.detachAppender(lines); + } + + private String run(MockHttpServletRequest request, int status) throws Exception { + new RequestTimingFilter().doFilter(request, new MockHttpServletResponse(), new MockFilterChain() { + @Override + public void doFilter(ServletRequest req, ServletResponse res) { + ((MockHttpServletResponse) res).setStatus(status); + } + }); + assertThat(lines.list).hasSize(1); + assertThat(lines.list.get(0).getLevel()).isEqualTo(Level.INFO); + return lines.list.get(0).getFormattedMessage(); + } + + @Test + void logsMethodPatternStatusAndMillisButNotThePathOrQuery() throws Exception { + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/games/4711"); + request.setQueryString("q=abc"); + request.setAttribute(HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE, "/api/games/{appid}"); + + assertThat(run(request, 200)).matches("GET /api/games/\\{appid} 200 \\d+ ms"); + } + + @Test + void logsADashForARequestNoHandlerTook() throws Exception { + assertThat(run(new MockHttpServletRequest("POST", "/some/path/42"), 404)).matches("POST - 404 \\d+ ms"); + } + + @Test + void logsStatus500WhenTheChainThrows() { + MockHttpServletRequest request = new MockHttpServletRequest("GET", "/api/x/1"); + request.setAttribute(HandlerMapping.BEST_MATCHING_PATTERN_ATTRIBUTE, "/api/x/{id}"); + + assertThatThrownBy(() -> new RequestTimingFilter().doFilter(request, + new MockHttpServletResponse(), (req, res) -> { throw new IllegalStateException("boom"); })) + .isInstanceOf(IllegalStateException.class); + + assertThat(lines.list).hasSize(1); + assertThat(lines.list.get(0).getFormattedMessage()).matches("GET /api/x/\\{id} 500 \\d+ ms"); + } + + @Test + void logsNothingForTheActuator() throws Exception { + new RequestTimingFilter().doFilter(new MockHttpServletRequest("GET", "/actuator/health"), + new MockHttpServletResponse(), new MockFilterChain()); + + assertThat(lines.list).isEmpty(); + } +}