From 0550f3fe9c1116344190a75728af46aa96a28435 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/core_service/configuration/RequestTimingFilter.java create mode 100644 src/test/java/core_service/configuration/RequestTimingFilterTest.java diff --git a/readme.md b/readme.md index ab2951b..a076b2a 100644 --- a/readme.md +++ b/readme.md @@ -846,6 +846,13 @@ Configuration comes from environment variables: | `APP_PSN_TOKEN_KEY` | Key for the stored PlayStation tokens, `openssl rand -base64 32` (optional; empty = PlayStation link off) | | `DB_PASSWORD` | Local PostgreSQL password | +### Request timing log + +`RequestTimingFilter` writes one INFO line to stdout per API request: method, handler path pattern, status and +duration, e.g. `GET /api/library/games 200 28 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/core_service/configuration/RequestTimingFilter.java b/src/main/java/core_service/configuration/RequestTimingFilter.java new file mode 100644 index 0000000..fd2ea7f --- /dev/null +++ b/src/main/java/core_service/configuration/RequestTimingFilter.java @@ -0,0 +1,54 @@ +package core_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/core_service/configuration/RequestTimingFilterTest.java b/src/test/java/core_service/configuration/RequestTimingFilterTest.java new file mode 100644 index 0000000..02e9830 --- /dev/null +++ b/src/test/java/core_service/configuration/RequestTimingFilterTest.java @@ -0,0 +1,83 @@ +package core_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(); + } +}