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

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

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

src/main/java/core_service/modules/library/repo/UserGameRepository.java

@@ -25,6 +25,7 @@ import java.time.LocalDate;
 import java.util.ArrayList;
 import java.util.Collection;
 import java.util.EnumMap;
+import java.util.EnumSet;
 import java.util.List;
 import java.util.Map;
 import java.util.Locale;
@@ -44,21 +45,22 @@ public interface UserGameRepository extends JpaRepository<UserGame, UserGameId>
     String LISTED = "ug.userId = :userId and ug.removedAt is null and ug.hiddenAt is null ";
 
     /**
-     * The filters of {@link #findOwnedGames}, shared by its value and count query. Needs the aliases {@code ug} and {@code sg}.
+     * The filters of {@link #findOwnedEntries}, shared by its value and count query. Needs the aliases {@code ug} and {@code sg}.
+     * Every subquery filters by {@code :userId} itself: Postgres does not pull a subquery inside an {@code or} up into a
+     * join, so without it the subquery is hashed over the rows of all users.
      */
     String OWNED_WHERE = "where ug.userId = :userId and ug.removedAt is null " +
             "and ((:hidden = true and ug.hiddenAt is not null) or (:hidden = false and ug.hiddenAt is null)) " +
             "and (:status is null or ug.status = :status) " +
             "and (:namePattern is null or (:hidden = true and lower(sg.name) like :namePattern escape '\\') " +
-            "     or (:hidden = false and exists (select 1 from UserGameEntryPlatform p " +
+            "     or (:hidden = false and ug.appid in (select p.appid from UserGameEntryPlatform p " +
             "         join SteamGame mg on mg.appid = p.memberAppid " +
-            "         where p.userId = ug.userId and p.appid = ug.appid and lower(mg.name) like :namePattern escape '\\'))) " +
+            "         where p.userId = :userId and lower(mg.name) like :namePattern escape '\\'))) " +
             "and (:maxMinutes is null or exists (select 1 from GameTimeToBeat t " +
             "     where t.appid = ug.appid and t.normallyMinutes <= :maxMinutes)) " +
-            "and (:hidden = true or exists (select 1 from CountedUserGame c " +
+            "and (:hidden = true or ug.appid in (select c.appid from CountedUserGame c where c.userId = :userId)) " +
-            "     where c.userId = ug.userId and c.appid = ug.appid)) " +
+            "and (:hidden = true or :anySource = true or ug.appid in (select p.appid from UserGameEntryPlatform p " +
-            "and (:hidden = true or exists (select 1 from UserGameEntryPlatform p " +
+            "     where p.userId = :userId and p.source in :sources))";
-            "     where p.userId = ug.userId and p.appid = ug.appid and p.source in :sources))";
 
     /**
      * The sort text of the set total: the own minutes for a hidden row. The query needs
@@ -360,9 +362,25 @@ public interface UserGameRepository extends JpaRepository<UserGame, UserGameId>
         return mood == null || mood == Mood.SPEEDRUN ? null : mood.name();
     }
 
+    // ponytail: the view is joined on every page, not only for the playtime sort: about +4 ms per page. Upgrade path:
+    // join it only for the playtime sort or the PLAYING status, with a second query.
+    @Query(value = "select ug from UserGame ug join SteamGame sg on sg.appid = ug.appid " +
+                   "left join UserGameEntryPlaytime ep on ep.userId = ug.userId and ep.appid = ug.appid " + OWNED_WHERE,
+           countQuery = "select count(ug) from UserGame ug join SteamGame sg on sg.appid = ug.appid " + OWNED_WHERE)
+    Page<UserGame> findOwnedEntries(@Param("userId") Long userId,
+                                    @Param("hidden") boolean hidden,
+                                    @Param("anySource") boolean anySource,
+                                    @Param("status") GameStatus status,
+                                    @Param("namePattern") String namePattern,
+                                    @Param("maxMinutes") Integer maxMinutes,
+                                    @Param("sources") Collection<GameSource> sources,
+                                    Pageable pageable);
+
     /**
      * One row per entry (see V43): a listed game is the counted edition of its set; a hidden game is a row of its own.
      *
+     * All sources skip the source filter: every counted entry has a platform row of its own source.
+     *
      * @param hidden true for only the hidden games, false for only the listed ones
      * @param status null for every status
      * @param namePattern a {@link #containsPattern} result, null for every name; a listed entry matches by the name of
@@ -371,18 +389,11 @@ public interface UserGameRepository extends JpaRepository<UserGame, UserGameId>
      * @param sources the sources one platform of the entry must have (a PlayStation title on a Steam row counts as
      *                PSN); never empty, and ignored for the hidden games
      */
-    // ponytail: the view is joined on every page, not only for the playtime sort: about +4 ms per page. Upgrade path:
+    default Page<UserGame> findOwnedGames(Long userId, boolean hidden, GameStatus status, String namePattern,
-    // join it only for the playtime sort or the PLAYING status, with a second query.
+                                          Integer maxMinutes, Collection<GameSource> sources, Pageable pageable) {
-    @Query(value = "select ug from UserGame ug join SteamGame sg on sg.appid = ug.appid " +
+        return findOwnedEntries(userId, hidden, sources.containsAll(EnumSet.allOf(GameSource.class)), status,
-                   "left join UserGameEntryPlaytime ep on ep.userId = ug.userId and ep.appid = ug.appid " + OWNED_WHERE,
+                namePattern, maxMinutes, sources, pageable);
-           countQuery = "select count(ug) from UserGame ug join SteamGame sg on sg.appid = ug.appid " + OWNED_WHERE)
+    }
-    Page<UserGame> findOwnedGames(@Param("userId") Long userId,
-                                  @Param("hidden") boolean hidden,
-                                  @Param("status") GameStatus status,
-                                  @Param("namePattern") String namePattern,
-                                  @Param("maxMinutes") Integer maxMinutes,
-                                  @Param("sources") Collection<GameSource> sources,
-                                  Pageable pageable);
 
     @Query("select distinct ug.source from UserGame ug where ug.userId = :userId and ug.removedAt is null")
     List<GameSource> findSources(@Param("userId") Long userId);

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

src/test/java/core_service/modules/library/repo/OwnedGamesQueryGuardTest.java

@@ -0,0 +1,177 @@
+package core_service.modules.library.repo;
+
+import core_service.modules.library.domain.GameSource;
+import core_service.modules.library.domain.GameStatus;
+import core_service.modules.library.domain.GameTimeToBeat;
+import core_service.modules.library.domain.SteamGame;
+import core_service.modules.library.domain.UserGame;
+import core_service.shared.test.AbstractPersistenceTest;
+import jakarta.persistence.EntityManager;
+import jakarta.persistence.Query;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.springframework.beans.factory.annotation.Autowired;
+import org.springframework.data.domain.PageRequest;
+import org.springframework.data.domain.Sort;
+import org.springframework.data.jpa.repository.query.QueryUtils;
+import org.springframework.jdbc.core.JdbcTemplate;
+
+import java.time.Instant;
+import java.util.ArrayList;
+import java.util.EnumSet;
+import java.util.List;
+import java.util.Set;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+/**
+ * Guards the rewrite of {@link UserGameRepository#OWNED_WHERE} for speed: it must return the same rows in the same
+ * order with the same total as the frozen text of the old query, for every filter of the Library.
+ */
+class OwnedGamesQueryGuardTest extends AbstractPersistenceTest {
+
+    private static final long USER_ID = 1L;
+    private static final long OTHER_USER_ID = 2L;
+    private static final int PAGE_SIZE = 2;
+
+    private static final String OLD_FROM = "from UserGame ug join SteamGame sg on sg.appid = ug.appid ";
+    private static final String OLD_SELECT = "select ug " + OLD_FROM
+            + "left join UserGameEntryPlaytime ep on ep.userId = ug.userId and ep.appid = ug.appid ";
+    private static final String OLD_COUNT = "select count(ug) " + OLD_FROM;
+    private static final String OLD_WHERE = "where ug.userId = :userId and ug.removedAt is null " +
+            "and ((:hidden = true and ug.hiddenAt is not null) or (:hidden = false and ug.hiddenAt is null)) " +
+            "and (:status is null or ug.status = :status) " +
+            "and (:namePattern is null or (:hidden = true and lower(sg.name) like :namePattern escape '\\') " +
+            "     or (:hidden = false and exists (select 1 from UserGameEntryPlatform p " +
+            "         join SteamGame mg on mg.appid = p.memberAppid " +
+            "         where p.userId = ug.userId and p.appid = ug.appid and lower(mg.name) like :namePattern escape '\\'))) " +
+            "and (:maxMinutes is null or exists (select 1 from GameTimeToBeat t " +
+            "     where t.appid = ug.appid and t.normallyMinutes <= :maxMinutes)) " +
+            "and (:hidden = true or exists (select 1 from CountedUserGame c " +
+            "     where c.userId = ug.userId and c.appid = ug.appid)) " +
+            "and (:hidden = true or exists (select 1 from UserGameEntryPlatform p " +
+            "     where p.userId = ug.userId and p.appid = ug.appid and p.source in :sources))";
+
+    private static final List<Sort> SORTS = List.of(
+            Sort.by(Sort.Direction.DESC, "playtimeMinutes"), Sort.by(Sort.Direction.ASC, "playtimeMinutes"),
+            Sort.by(Sort.Direction.DESC, "lastSeenAt"), Sort.by(Sort.Direction.DESC, "firstSeenAt"),
+            Sort.by(Sort.Direction.DESC, "rating"), Sort.by(Sort.Direction.DESC, "priority"));
+
+    @Autowired
+    private UserGameRepository userGameRepository;
+
+    @Autowired
+    private SteamGameRepository steamGameRepository;
+
+    @Autowired
+    private GameTimeToBeatRepository gameTimeToBeatRepository;
+
+    @Autowired
+    private JdbcTemplate jdbc;
+
+    @Autowired
+    private EntityManager entityManager;
+
+    @BeforeEach
+    void seed() {
+        String[] names = {"Half-Life 2", "Half-Life 2: Episode One", "Portal 2", "Half-Life Alyx", "Episode Zero",
+                "Manual Game", "Console Game", "Hidden Half-Life", "Removed Game", "Plain Game"};
+        List<SteamGame> catalog = new ArrayList<>();
+        for (int i = 0; i < names.length; i++) catalog.add(new SteamGame(100L + i, names[i], null, Instant.now()));
+        steamGameRepository.saveAll(catalog);
+
+        Instant now = Instant.now();
+        for (long user : new long[]{USER_ID, OTHER_USER_ID}) {
+            for (int i = 0; i < names.length; i++) {
+                userGameRepository.save(new UserGame(user, 100L + i, (i * 137) % 600, now.minusSeconds(i * 3600L),
+                        now.minusSeconds((names.length - i) * 7200L)));
+            }
+        }
+        // 100 and 101 are two editions of one set; 101 is the lesser one whose name is the only "episode" match
+        jdbc.update("delete from game_link");
+        jdbc.update("insert into game_link (appid, set_id) values (100, 1), (101, 1), (103, 2), (104, 2)");
+        entityManager.flush();
+        for (long user : new long[]{USER_ID, OTHER_USER_ID}) {
+            update(user, 100, "status = 'PLAYING', rating = 4, priority = 'HIGH'");
+            update(user, 102, "status = 'BACKLOG', priority = 'LOW'");
+            update(user, 103, "status = 'PLAYING', rating = 5");
+            update(user, 104, "status = 'BACKLOG', priority = 'MEDIUM'");
+            update(user, 105, "source = 'MANUAL', status = 'BACKLOG'");
+            update(user, 106, "source = 'PSN', status = 'PLAYING', rating = 5");
+            update(user, 107, "hidden_at = now()");
+            update(user, 108, "removed_at = now()");
+            jdbc.update("insert into user_psn_title (user_id, psn_key, state, appid, platform, playtime_minutes) "
+                    + "values (?, 'c1', 'STEAM_OWNED', 102, 'PS5', 700)", user);
+        }
+        // The other user's state differs, so a subquery without its userId filter returns other rows. Set 2 is
+        // {103, 104}: 104 has more playtime and is the counted edition. User 1 lost 103, so only user 2's entry 104
+        // matches the name "half". User 2 lost 101, so its edition 100 is counted (for user 1 it is not). User 2 has
+        // 104 on PSN only, where user 1 has it on Steam.
+        update(USER_ID, 103, "removed_at = now()");
+        update(OTHER_USER_ID, 101, "removed_at = now()");
+        update(OTHER_USER_ID, 104, "source = 'PSN'");
+        gameTimeToBeatRepository.saveAll(List.of(
+                new GameTimeToBeat(100L, 500, 700, 1000, now),
+                new GameTimeToBeat(102L, 300, 480, 900, now),
+                new GameTimeToBeat(103L, 300, 480, 900, now),
+                new GameTimeToBeat(104L, null, null, null, now)));
+        entityManager.flush();
+        entityManager.clear();
+    }
+
+    private void update(long user, long appid, String set) {
+        jdbc.update("update user_game set " + set + " where user_id = ? and appid = ?", user, appid);
+    }
+
+    @Test
+    void findOwnedGames_MatchesTheOldQueryForEveryFilter() {
+        List<Set<GameSource>> sourceSets = List.of(EnumSet.allOf(GameSource.class), EnumSet.of(GameSource.PSN),
+                EnumSet.of(GameSource.STEAM, GameSource.MANUAL));
+        for (boolean hidden : new boolean[]{false, true}) {
+            for (GameStatus status : new GameStatus[]{null, GameStatus.PLAYING, GameStatus.BACKLOG}) {
+                for (String name : new String[]{null, "half", "episode"}) {
+                    for (Integer maxMinutes : new Integer[]{null, 600}) {
+                        for (Set<GameSource> sources : sourceSets) {
+                            for (Sort sort : SORTS) {
+                                for (int page = 0; page < 2; page++) {
+                                    String combination = "hidden=" + hidden + " status=" + status + " name=" + name
+                                            + " maxMinutes=" + maxMinutes + " sources=" + sources + " sort=" + sort
+                                            + " page=" + page;
+                                    String pattern = UserGameRepository.containsPattern(name);
+                                    var actual = userGameRepository.findOwnedGames(USER_ID, hidden, status, pattern,
+                                            maxMinutes, sources, PageRequest.of(page, PAGE_SIZE, UserGameRepository.querySort(sort)));
+                                    assertThat(actual.getContent().stream().map(UserGame::getAppid).toList())
+                                            .as(combination)
+                                            .isEqualTo(oldAppids(hidden, status, pattern, maxMinutes, sources, sort, page));
+                                    assertThat(actual.getTotalElements()).as(combination)
+                                            .isEqualTo(oldTotal(hidden, status, pattern, maxMinutes, sources));
+                                }
+                            }
+                        }
+                    }
+                }
+            }
+        }
+    }
+
+    @SuppressWarnings("unchecked")
+    private List<Long> oldAppids(boolean hidden, GameStatus status, String pattern, Integer maxMinutes,
+                                 Set<GameSource> sources, Sort sort, int page) {
+        String jpql = QueryUtils.applySorting(OLD_SELECT + OLD_WHERE, UserGameRepository.querySort(sort), "ug");
+        Query query = bind(entityManager.createQuery(jpql), hidden, status, pattern, maxMinutes, sources);
+        query.setFirstResult(page * PAGE_SIZE).setMaxResults(PAGE_SIZE);
+        return ((List<UserGame>) query.getResultList()).stream().map(UserGame::getAppid).toList();
+    }
+
+    private long oldTotal(boolean hidden, GameStatus status, String pattern, Integer maxMinutes, Set<GameSource> sources) {
+        return (Long) bind(entityManager.createQuery(OLD_COUNT + OLD_WHERE), hidden, status, pattern, maxMinutes, sources)
+                .getSingleResult();
+    }
+
+    private Query bind(Query query, boolean hidden, GameStatus status, String pattern, Integer maxMinutes,
+                       Set<GameSource> sources) {
+        return query.setParameter("userId", USER_ID).setParameter("hidden", hidden).setParameter("status", status)
+                .setParameter("namePattern", pattern).setParameter("maxMinutes", maxMinutes)
+                .setParameter("sources", sources);
+    }
+}