Fix bug in open match filling and added some matchmaking logs.

dist/app/Console/Commands/MatchmakingCleanup.php

@@ -9,15 +9,17 @@
 use Illuminate\Support\Carbon;
 use Illuminate\Support\Facades\Cache;
 use Illuminate\Support\Facades\DB;
+use Illuminate\Support\Facades\Log;
 
 class MatchmakingCleanup extends Command
 {
     // After how many minutes a queued palyer gets removed from the queue or from an open match in Minutes.
-    const PLAYER_HEARTBEAT_TIMEOUT = 0.25;
+    const PLAYER_HEARTBEAT_TIMEOUT = 0.5;
 
     // After how many minutes a closed game gets deleted automatically when it hasn't been killed normally yet.
     const GAME_MAX_TIME = 11;
 
+    // In Seconds
     const CREATED_GAME_TIMEOUT = 30;
 
     /**
@@ -39,20 +41,29 @@ class MatchmakingCleanup extends Command
      */
     public function handle()
     {
+        $log = Log::channel('matchmaking_cleanup');
+
         // Delete queued players that haven't sent a queue resquest in the given period of time,
         // which means they crashed or closed the game without sending cancle.
-        QueuedPlayer::where('updated_at', '<', Carbon::now()->subMinutes(static::PLAYER_HEARTBEAT_TIMEOUT))
+        $cleanedQueuedPlayers = QueuedPlayer::where('updated_at', '<', Carbon::now()->subSeconds(static::PLAYER_HEARTBEAT_TIMEOUT * 60))
             ->delete();
 
-        Game::where('status', '=', MatchStatus::Closed->value)
-            ->where('updated_at', '<', Carbon::now()->subMinutes(static::GAME_MAX_TIME))
+        $log->info('Queued players: ' . json_encode($cleanedQueuedPlayers, JSON_PRETTY_PRINT));
+
+        $deletedClosedGames =  Game::where('status', '=', MatchStatus::Closed->value)
+            ->where('updated_at', '<', Carbon::now()->subSeconds(static::GAME_MAX_TIME * 60))
             ->delete();
 
+        $log->info('Deleted Closed games: ' . json_encode($deletedClosedGames, JSON_PRETTY_PRINT));
+
+
         // delete games where the hunter crashed on loading into the arena, leaving the game stuck at created
-        Game::where('status', '=', MatchStatus::Created)
+        $deletedCreatedGames = Game::where('status', '=', MatchStatus::Created)
             ->where('created_at', '<', Carbon::now()->subSeconds(static::CREATED_GAME_TIMEOUT))
             ->delete();
 
+        $log->info('Deleted Stuck Created games: ' . json_encode($deletedCreatedGames, JSON_PRETTY_PRINT));
+
         // Select User Ids that joined a game and haven't sent the match request for a period of time
         // This porpably means they crashed or never joined the game in the first place.
         $usersToRemove = DB::table('game_user')->join('games', 'game_user.game_id', '=', 'games.id')
@@ -60,7 +71,7 @@ public function handle()
                 MatchStatus::Created->value,
                 MatchStatus::Opened->value,
             ])
-            ->where('game_user.updated_at', '<', Carbon::now()->subMinutes(static::PLAYER_HEARTBEAT_TIMEOUT))
+            ->where('game_user.updated_at', '<', Carbon::now()->subSeconds(static::PLAYER_HEARTBEAT_TIMEOUT * 60))
             ->get(['user_id']);
 
         $userIdArray = [];
@@ -68,6 +79,8 @@ public function handle()
             $userIdArray[] = $user->user_id;
         }
 
+        $log->info('Deleting players that are in a mach, but didnt send a heartbeat: ' . json_encode($usersToRemove, JSON_PRETTY_PRINT));
+
         // Delete a game if one of the to be removed players is the host.
         Game::whereIn('creator_user_id', $userIdArray)->delete();
 

dist/app/Console/Commands/ProcessMatchmaking.php

@@ -70,6 +70,13 @@ public function handle(): void
 
         $this->tryFillOpenGames($hunters, $runners);
 
+        static::log()->info('Users in Queue after trying to fill:'. json_encode([
+                'hunters' => $hunters->toArray(),
+                'runners' => $runners->toArray(),
+            ],
+                JSON_PRETTY_PRINT
+            ));
+
         $playerCount = $this->getTotalPlayersCount($players);
         $availableMatchConfigs = MatchConfiguration::getAvailableMatchConfigs($playerCount->runners, $playerCount->hunters);
 
@@ -126,6 +133,7 @@ protected function tryFillOpenGames(Collection|array &$hunters, Collection|array
         static::log()->info('Found Open Matches:' . json_encode($openGames->toArray(),JSON_PRETTY_PRINT));
 
         foreach ($openGames as $game) {
+            static::log()->info("Game $game->id current players: ". json_encode($game->players));
             $neededPlayers = $game->remainingPlayerCount();
 
             // game is full and doesn't need filling
@@ -133,6 +141,7 @@ protected function tryFillOpenGames(Collection|array &$hunters, Collection|array
                 continue;
 
             if($neededPlayers->hunters > 0) {
+                static::log()->info("Game $game->id needs a hunter");
                 $hunterGroupsSet = $this->determineMatchingPlayers($hunters, $neededPlayers->hunters);
 
                 // see if there are any group combinations possible to fill the game
@@ -141,6 +150,7 @@ protected function tryFillOpenGames(Collection|array &$hunters, Collection|array
 
                 // use biggest groups first
                 rsort($hunterGroupsSet, SORT_NUMERIC);
+                static::log()->info("Game $game->id Try fill game group sets: ". json_encode($runnerGroupSet));
 
                 foreach ($hunterGroupsSet as $groupSize) {
                     $foundQueuedPlayerIndex = $hunters->search(function (QueuedPlayer $hunter) use ($groupSize) {
@@ -159,6 +169,7 @@ protected function tryFillOpenGames(Collection|array &$hunters, Collection|array
             }
 
             if($neededPlayers->runners > 0) {
+                static::log()->info("Game $game->id needs a runner");
                 $runnerGroupSet = $this->determineMatchingPlayers($runners, $neededPlayers->runners);
 
                 // see if there are any group combinations possible to fill the game
@@ -168,6 +179,8 @@ protected function tryFillOpenGames(Collection|array &$hunters, Collection|array
                 // use biggest groups first
                 rsort($runnerGroupSet, SORT_NUMERIC);
 
+                static::log()->info("Game $game->id Try fill game group sets: ". json_encode($runnerGroupSet));
+
                 foreach ($runnerGroupSet as $groupSize) {
                     $foundQueuedPlayerIndex = $runners->search(function (QueuedPlayer $runner) use ($groupSize) {
                         return ($runner->following_users_count + 1) === $groupSize;
@@ -175,7 +188,7 @@ protected function tryFillOpenGames(Collection|array &$hunters, Collection|array
 
                     $foundRunner = $runners->pull($foundQueuedPlayerIndex);
                     static::log()->info('Filled runner slot on open game.'. json_encode([
-                            'hunter' => $foundHunter,
+                            'runner' => $foundRunner,
                             'game' => $game,
                         ],
                             JSON_PRETTY_PRINT)

dist/app/Console/Kernel.php

@@ -13,8 +13,8 @@ class Kernel extends ConsoleKernel
     protected function schedule(Schedule $schedule): void
     {
         $schedule->command('model:prune')->daily();
-        $schedule->command('matchmaking:process')->everyTenSeconds();
-        $schedule->command('matchmaking:cleanup')->everyTwentySeconds();
+        $schedule->command('matchmaking:process')->everyFiveSeconds();
+        $schedule->command('matchmaking:cleanup')->everyFifteenSeconds();
     }
 
     /**

dist/config/logging.php

@@ -121,6 +121,13 @@
             'replace_placeholders' => true,
         ],
 
+        'matchmaking_cleanup' => [
+            'driver' => 'daily',
+            'path' => storage_path('logs/matchmaking_cleanup/cleanup.log'),
+            'level' => 'info',
+            'replace_placeholders' => true,
+        ],
+
         'daily' => [
             'driver' => 'daily',
             'path' => storage_path('logs/laravel.log'),