cleborys
commented
4 years ago It seems to me that the failing assert is always the one after the second gc.collect(), here:
https://github.com/FAForever/server/blob/737e71ea07a7627c384b4dfd5a6a752d0888ce42/tests/integration_tests/test_game.py#L409
Here are some logs comparing a failed test run with a "normal" test run intentionally failed after the assert above.
A normal test run always ends with a broadcast game_info "closed" as expected:
TRACE UnitTestServer:__init__.py:114 ]]: {'command': 'game_info', 'visibility': 'public', 'password_protected': False, 'uid': 41949, 'title': "test's game", 'state': 'closed', 'game_type': 'custom', 'featured_mod': 'faf', 'sim_mods': {}, 'mapname': 'scmp_007', 'map_file_path': 'maps/scmp_007.zip', 'host': 'test', 'num_players': 2, 'max_players': 12, 'launched_at': 1598967323.1251912, 'teams': {1: ['test', 'Rhiza']}}For a failed test run, the game_info "closed" happens much earlier, right after the game creation and before players join
(added blank lines and comment for readability)
DEBUG CustomGame.41949:game.py:109 Game(41949,test,maps/scmp_007.zip,0) created
DEBUG GameConnection:gameconnection.py:45 GameConnection initializing
TRACE LobbyConnection:lobbyconnection.py:1075 >> test: {'command': 'game_launch', 'args': ['/numgames', 5], 'uid': 41949, 'mod': 'faf', 'name': "test's game", 'init_mode': 0}
TRACE UnitTestServer:__init__.py:114 ]]: {'command': 'matchmaker_info', 'queues': [{'queue_name': 'tmm2v2', 'queue_pop_time': '2020-09-01T13:29:21.845675+00:00', 'num_players': 0, 'boundary_80s': [], 'boundary_75s': [], 'team_size': 2}, {'queue_name': 'ladder1v1', 'queue_pop_time': '2020-09-01T13:29:21.845422+00:00', 'num_players': 0, 'boundary_80s': [], 'boundary_75s': [], 'team_size': 1}]}
TRACE UnitTestServer:__init__.py:114 ]]: {'command': 'player_info', 'players': [{'id': 3, 'login': 'Rhiza', 'country': '', 'clan': '123', 'ratings': {'global': {'rating': (1650.0, 62.52), 'number_of_games': 2}, 'ladder_1v1': {'rating': (1650.0, 62.52), 'number_of_games': 2}}, 'global_rating': (1650.0, 62.52), 'ladder_rating': (1650.0, 62.52), 'number_of_games': 2}]}
% now the game_info message:
TRACE UnitTestServer:__init__.py:114 ]]: {'command': 'game_info', 'visibility': 'public', 'password_protected': False, 'uid': 41949, 'title': "test's game", 'state': 'closed', 'game_type': 'custom', 'featured_mod': 'faf', 'sim_mods': {}, 'mapname': 'scmp_007', 'map_file_path': 'maps/scmp_007.zip', 'host': 'test', 'num_players': 0, 'max_players': 12, 'launched_at': None, 'teams': {}}
TRACE LobbyConnection:lobbyconnection.py:165 << test: {'target': 'game', 'command': 'GameState', 'args': ['Idle']}
INFO CustomGame.41949:game.py:311 Added game connection GameConnection(Player(test, 1, (2000.0, 125.0), (2000.0, 125.0)), Game(41949,test,maps/scmp_007.zip,0))
TRACE LobbyConnection:lobbyconnection.py:165 << test: {'target': 'game', 'command': 'GameState', 'args': ['Lobby']}
TRACE GameConnection:gameconnection.py:99 >> test: {'command': 'HostGame', 'args': ['scmp_007'], 'target': 'game'}
TRACE LobbyConnection:lobbyconnection.py:165 << Rhiza: {'command': 'game_join', 'uid': 41949}note the 'num_players': 0 in the message.
I don't know what's triggering it, but I would guess that that is messing up the wait here:
https://github.com/FAForever/server/blob/737e71ea07a7627c384b4dfd5a6a752d0888ce42/tests/integration_tests/test_game.py#L403-L406
I though maybe the game is timing out and broadcast as closed, but that would show up in the logs and it doesn't.
If the test were allowed to continue and just wait, it would eventually receive another game_info message after the game has been properly closed again. Indeed the tests passes 1.000 times in a row if I add and msg["num_players"] == 2 as a condition to the protocol await linked above. Before I would only very rarely pass 100 consecutive runs.
Here's all game_infos grepped from the logs:
successful run:
TRACE LobbyConnection:lobbyconnection.py:1075 >> test: {'command': 'game_info', 'games': []}
TRACE LobbyConnection:lobbyconnection.py:1075 >> Rhiza: {'command': 'game_info', 'games': []}
TRACE UnitTestServer:__init__.py:114 ]]: {'command': 'game_info', 'visibility': 'public', 'password_protected': False, 'uid': 41949, 'title': "test's game", 'state': 'closed', 'game_type': 'custom', 'featured_mod': 'faf', 'sim_mods': {}, 'mapname': 'scmp_007', 'map_file_path': 'maps/scmp_007.zip', 'host': 'test', 'num_players': 2, 'max_players': 12, 'launched_at': 1598967323.1251912, 'teams': {1: ['test', 'Rhiza']}}failed run:
TRACE LobbyConnection:lobbyconnection.py:1075 >> test: {'command': 'game_info', 'games': []}
TRACE LobbyConnection:lobbyconnection.py:1075 >> Rhiza: {'command': 'game_info', 'games': []}
TRACE UnitTestServer:__init__.py:114 ]]: {'command': 'game_info', 'visibility': 'public', 'password_protected': False, 'uid': 41949, 'title': "test's game", 'state': 'closed', 'game_type': 'custom', 'featured_mod': 'faf', 'sim_mods': {}, 'mapname': 'scmp_007', 'map_file_path': 'maps/scmp_007.zip', 'host': 'test', 'num_players': 0, 'max_players': 12, 'launched_at': None, 'teams': {}}
TRACE UnitTestServer:__init__.py:114 ]]: {'command': 'game_info', 'visibility': 'public', 'password_protected': False, 'uid': 41949, 'title': "test's game", 'state': 'playing', 'game_type': 'custom', 'featured_mod': 'faf', 'sim_mods': {}, 'mapname': 'scmp_007', 'map_file_path': 'maps/scmp_007.zip', 'host': 'test', 'num_players': 2, 'max_players': 12, 'launched_at': 1598966960.856856, 'teams': {1: ['test', 'Rhiza']}}Which also makes me wonder why the successful run doesn't have the additional game_info broadcast with 'state': playing.
Askaholic
The test that checks for references to the game object to be cleaned up tends to fail randomly, which is annoying for travis builds.
https://github.com/FAForever/server/blob/737e71ea07a7627c384b4dfd5a6a752d0888ce42/tests/integration_tests/test_game.py#L327