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

@@ -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

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/");
+    }
+}

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<ILoggingEvent> 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();
+    }
+}