Fix pop timer crash (#720)

* Clean up flaky test

Test was flaky due to expensive autospecing

* Make CombinedSearch return an integer for failed_matching_attempts

* Wrap queue pop loop in try block

server/matchmaker/matchmaker_queue.py

@@ -95,17 +95,26 @@ async def queue_pop_timer(self) -> None:
         """
         self._logger.debug("MatchmakerQueue initialized for %s", self.name)
         while self._is_running:
-            await self.timer.next_pop()
+            try:
+                await self.timer.next_pop()
 
-            await self.find_matches()
+                await self.find_matches()
 
-            number_of_unmatched_searches = len(self._queue)
-            metrics.unmatched_searches.labels(self.name).set(number_of_unmatched_searches)
+                number_of_unmatched_searches = len(self._queue)
+                metrics.unmatched_searches.labels(self.name).set(
+                    number_of_unmatched_searches
+                )
 
-            # Any searches in the queue at this point were unable to find a
-            # match this round and will have higher priority next round.
+                # Any searches in the queue at this point were unable to find a
+                # match this round and will have higher priority next round.
 
-            self.game_service.mark_dirty(self)
+                self.game_service.mark_dirty(self)
+            except Exception:
+                self._logger.exception(
+                    "Unexpected error during queue pop timer loop!"
+                )
+                # To avoid potential busy loops
+                await asyncio.sleep(1)
 
     async def search(self, search: Search) -> None:
         """

server/matchmaker/search.py

@@ -271,9 +271,8 @@ def raw_ratings(self):
         return list(itertools.chain(*[s.raw_ratings for s in self.searches]))
 
     @property
-    def failed_matching_attempts(self) -> List[int]:
-        """Used for logging so returning a different type here is fine"""
-        return [search.failed_matching_attempts for search in self.searches]
+    def failed_matching_attempts(self) -> int:
+        return max(search.failed_matching_attempts for search in self.searches)
 
     def register_failed_matching_attempt(self):
         for search in self.searches:

tests/data/test-data.sql

@@ -78,6 +78,8 @@ insert into login (id, login, email, password, steamid, create_time) values
   (102, 'ladder3', 'ladder3@example.com', SHA2('ladder3', 256), null, '2000-01-01 00:00:00'),
   (103, 'ladder4', 'ladder4@example.com', SHA2('ladder4', 256), null, '2000-01-01 00:00:00'),
   (104, 'ladder_ban', 'ladder_ban@example.com', SHA2('ladder_ban', 256), null, '2000-01-01 00:00:00'),
+  (105, 'tmm1', 'tmm1@example.com', SHA2('tmm1', 256), null, '2000-01-01 00:00:00'),
+  (106, 'tmm2', 'tmm2@example.com', SHA2('tmm2', 256), null, '2000-01-01 00:00:00'),
   (200, 'banme', 'banme@example.com', SHA2('banme', 256), null, '2000-01-01 00:00:00'),
   (201, 'ban_revoked', 'ban_revoked@example.com', SHA2('ban_revoked', 256), null, '2000-01-01 00:00:00'),
   (202, 'ban_expired', 'ban_expired@example.com', SHA2('ban_expired', 256), null, '2000-01-01 00:00:00'),
@@ -118,7 +120,9 @@ insert into leaderboard_rating (login_id, mean, deviation, total_games, leaderbo
   (101, 1500, 500, 0, 1),
   (101, 1500, 500, 0, 2),
   (102, 1500, 500, 0, 1),
-  (102, 1500, 500, 0, 2)
+  (102, 1500, 500, 0, 2),
+  (105, 1400, 150, 20, 3),
+  (106, 1500, 75, 20, 3)
 ;
 
 -- legacy table for global rating

tests/integration_tests/test_game.py

@@ -38,7 +38,7 @@ async def join_game(proto: Protocol, uid: int):
 
 
 async def client_response(proto):
-    msg = await read_until_command(proto, "game_launch")
+    msg = await read_until_command(proto, "game_launch", timeout=5)
     await open_fa(proto)
     return msg
 

tests/integration_tests/test_teammatchmaker.py

@@ -217,6 +217,71 @@ async def test_game_matchmaking_with_parties(lobby_server):
         assert msg["faction"] == i + 1
 
 
+@fast_forward(30)
+async def test_newbie_matchmaking_with_parties(lobby_server):
+    # Two completely new tmm players
+    id1, _, proto1 = await connect_and_sign_in(
+        ("ladder1", "ladder1"), lobby_server
+    )
+    id2, _, proto2 = await connect_and_sign_in(
+        ("ladder2", "ladder2"), lobby_server
+    )
+    # Two more experienced players
+    _, _, proto3 = await connect_and_sign_in(
+        ("tmm1", "tmm1"), lobby_server
+    )
+    _, _, proto4 = await connect_and_sign_in(
+        ("tmm2", "tmm2"), lobby_server
+    )
+    protos = (proto1, proto2, proto3, proto4)
+
+    await asyncio.gather(*[
+        read_until_command(proto, "game_info") for proto in protos
+    ])
+
+    # Setup new players in a party
+    await proto1.send_message({
+        "command": "invite_to_party",
+        "recipient_id": id2
+    })
+    await read_until_command(proto2, "party_invite")
+    await proto2.send_message({
+        "command": "accept_party_invite",
+        "sender_id": id1
+    })
+    await read_until_command(proto1, "update_party")
+
+    # Queue all players
+    await proto1.send_message({
+        "command": "game_matchmaking",
+        "queue_name": "tmm2v2",
+        "state": "start",
+    })
+    # The tmm players are queuing solo
+    await proto3.send_message({
+        "command": "game_matchmaking",
+        "queue_name": "tmm2v2",
+        "state": "start",
+    })
+    await proto4.send_message({
+        "command": "game_matchmaking",
+        "queue_name": "tmm2v2",
+        "state": "start",
+    })
+
+    msgs = await asyncio.gather(*[client_response(proto) for proto in protos])
+
+    uid = set(msg["uid"] for msg in msgs)
+    assert len(uid) == 1
+    for msg in msgs:
+        assert msg["init_mode"] == 1
+        assert "None" not in msg["name"]
+        assert msg["mod"] == "faf"
+        assert msg["expected_players"] == 4
+        assert msg["team"] in (2, 3)
+        assert msg["map_position"] in (1, 2, 3, 4)
+
+
 @fast_forward(60)
 async def test_game_matchmaking_multiqueue_timeout(lobby_server):
     protos, _ = await connect_players(lobby_server)

tests/unit_tests/test_matchmaker_queue.py

@@ -109,8 +109,16 @@ def test_search_threshold_of_team_new_players_is_low(player_factory):
 
 @given(rating1=st_rating(), rating2=st_rating())
 def test_search_quality_equivalence(player_factory, rating1, rating2):
-    p1 = player_factory("Player1", ladder_rating=rating1)
-    p2 = player_factory("Player2", ladder_rating=rating2)
+    p1 = player_factory(
+        "Player1",
+        ladder_rating=rating1,
+        with_lobby_connection=False
+    )
+    p2 = player_factory(
+        "Player2",
+        ladder_rating=rating2,
+        with_lobby_connection=False
+    )
     s1 = Search([p1])
     s2 = Search([p2])
     assert s1.quality_with(s2) == s2.quality_with(s1)
@@ -199,13 +207,20 @@ async def test_search_await(matchmaker_players):
 
 def test_combined_search_attributes(matchmaker_players):
     p1, p2, p3, _, _, _ = matchmaker_players
-    search = CombinedSearch(Search([p1, p2]), Search([p3]))
+    s1 = Search([p1, p2])
+    s2 = Search([p3])
+    s2.register_failed_matching_attempt()
+    search = CombinedSearch(s1, s2)
     assert search.players == [p1, p2, p3]
     assert search.raw_ratings == [
         p1.ratings[RatingType.LADDER_1V1],
         p2.ratings[RatingType.LADDER_1V1],
         p3.ratings[RatingType.LADDER_1V1]
     ]
+    assert search.failed_matching_attempts == 1
+
+    search.register_failed_matching_attempt()
+    assert search.failed_matching_attempts == 2
 
 
 def test_queue_time_until_next_pop(queue_factory):