Background script logging + fix autorun launching scripts

extra/provision.sh

@@ -60,6 +60,7 @@ DOMAIN="none"
 EMAIL="none"
 CODE_PATH="/vagrant"
 CTF_PATH="/var/www/fbctf"
+LOG_PATH="/var/log/fbctf"
 HHVM_CONFIG_PATH="/etc/hhvm/server.ini"
 DOCKER=false
 MULTIPLE_SERVERS=false
@@ -332,6 +333,10 @@ fi
     log "Creating custom logos folder, and setting ownership to www-data"
     sudo mkdir -p "$CTF_PATH/src/data/customlogos"
     sudo chown -R www-data:www-data "$CTF_PATH/src/data/customlogos"
+
+    log "Creating scripts log folder, and setting ownership to www-data"
+    sudo mkdir -p "$LOG_PATH"
+    sudo chown -R www-data:www-data "$LOG_PATH"
 fi
 
 # If multiple servers are being utilized, ensure provision was called from the "cache" server

src/Utils.php

@@ -108,6 +108,10 @@ public static function getFILES(): Map<string, array<string, mixed>> {
     return new Map($_FILES);
   }
 
+  public static function get_src_root() : string {
+    return preg_replace(':/src/.*$:', '/src', __DIR__);
+  }
+
   public static function redirect(string $location): void {
     header('Location: '.$location);
   }
@@ -140,4 +144,21 @@ public static function error_response(
   ): string {
     return self::request_response('ERROR', $msg, $redirect);
   }
+
+  public static function logMessage(
+    string $message
+  ): void {
+    $date = date('m/d/Y h:i:s a', time());
+    $message = "[$date] $message\n";
+
+    if (php_sapi_name() === 'cli') {
+      fwrite(STDOUT, $message);
+    } else {
+      $filename = '/var/log/fbctf/web.log';
+      if ($handle = fopen($filename, 'a')) {
+        fwrite($handle, $message);
+        fclose($handle);
+      }
+    }
+  }
 }

src/models/Control.php

@@ -52,7 +52,37 @@ class Control extends Model {
     if ($result->numRows() > 0) {
       $pid = intval(must_have_idx($result->mapRows()[0], 'pid'));
     }
-    return $pid;
+
+    // Check that the process is actually running
+    $actual_pid = await self::genRunningScriptPid($name);
+    if ($pid == $actual_pid) {
+      return $pid;
+    }
+    if ($actual_pid == 0 && $pid != 0) {
+      Utils::logMessage("Warning: Script ($name) started as PID $pid but is no longer running");
+      await self::genStopScriptLog($pid);
+    } else if ($actual_pid != 0 && $pid == 0) {
+      Utils::logMessage("Warning: Script ($name) was not started, but is running as PID $actual_pid");
+    } else if ($actual_pid != $pid) {
+      Utils::logMessage("Warning: Script ($name) started as PID $pid but is actually running as $actual_pid");
+      await self::genStopScriptLog($pid);
+    }
+
+    return $actual_pid;
+  }
+
+  public static async function genRunningScriptPid(string $name): Awaitable<int> {
+    $lines = array();
+    exec( "ps -C hhvm --format 'pid args' | grep '$name.php'", $lines );
+    if (count($lines) === 0) {
+      return 0;
+    } else if (count($lines) > 1) {
+      Utils::logMessage("Error: multiple instances of ($name.php) running!");
+    }
+
+    $matches = array();
+    $results = preg_match('/\s*([0-9]+)\s/', $lines[0], $matches);
+    return $results > 0 ? intval($matches[1]) : 0;
   }
 
   public static async function genClearScriptLog(): Awaitable<void> {
@@ -65,6 +95,7 @@ class Control extends Model {
   }
 
   public static async function genBegin(): Awaitable<void> {
+    Utils::logMessage('Starting game');
     await \HH\Asio\va(
       Announcement::genDeleteAll(), // Clear announcements log
       ActivityLog::genDeleteAll(), // Clear activity log
@@ -129,13 +160,15 @@ class Control extends Model {
       Progressive::genReset(), // Reset and kick off progressive scoreboard
     );
 
+    Utils::logMessage('Starting background scripts');
     await \HH\Asio\va(
       Progressive::genRun(),
       Level::genBaseScoring(), // Kick off scoring for bases
     );
   }
 
   public static async function genEnd(): Awaitable<void> {
+    Utils::logMessage('Ending game');
     await \HH\Asio\va(
       Announcement::genCreateAuto('Game has ended!'), // Announce game ending
       ActivityLog::genCreateGenericLog('Game has ended!'), // Log game ending
@@ -152,6 +185,7 @@ class Control extends Model {
     $game_paused = $pause->getValue() === '1';
 
     if (!$game_paused) {
+      Utils::logMessage('Stopping background scripts');
       // Stop bases scoring process
       // Stop progressive scoreboard process
       await \HH\Asio\va(Level::genStopBaseScoring(), Progressive::genStop());
@@ -162,6 +196,7 @@ class Control extends Model {
   }
 
   public static async function genPause(): Awaitable<void> {
+    Utils::logMessage('Pausing game');
     await \HH\Asio\va(
       Announcement::genCreateAuto('Game has been paused!'), // Announce game paused
       ActivityLog::genCreateGenericLog('Game has been paused!'), // Log game paused
@@ -179,6 +214,7 @@ class Control extends Model {
   }
 
   public static async function genUnpause(): Awaitable<void> {
+    Utils::logMessage('Unpausing game');
     await Configuration::genUpdate('scoring', '1'); // Enable scoring
     list($config_pause_ts, $config_start_ts, $config_end_ts) =
       await \HH\Asio\va(
@@ -260,43 +296,62 @@ class Control extends Model {
   public static async function genRunAutoRunScript(): Awaitable<void> {
     $autorun_status = await Control::checkScriptRunning('autorun');
     if ($autorun_status === false) {
+      Utils::logMessage('Starting background script: autorun');
       $autorun_location = escapeshellarg(
         must_have_string(Utils::getSERVER(), 'DOCUMENT_ROOT').
         '/scripts/autorun.php',
       );
       $cmd =
         'hhvm -vRepo.Central.Path=/var/run/hhvm/.hhvm.hhbc_autorun '.
         $autorun_location.
-        ' > /dev/null 2>&1 & echo $!';
+        ' >> /var/log/fbctf/autorun.log 2>&1 & echo $!';
+      Utils::logMessage("Using command: [$cmd]");
       $pid = shell_exec($cmd);
       await Control::genStartScriptLog(intval($pid), 'autorun', $cmd);
     }
   }
 
+  public static async function genRunScript(
+    string $name
+  ): Awaitable<void> {
+    Utils::logMessage("Starting background script: $name");
+    $running = await self::checkScriptRunning($name);
+    if ($running) {
+      Utils::logMessage("Warning: $name is already running");
+    }
+
+    $document_root = Utils::get_src_root();
+    $cmd =
+      "hhvm -vRepo.Central.Path=/var/run/hhvm/.hhvm.hhbc_$name ".
+      $document_root.
+      "/scripts/$name.php >> /var/log/fbctf/$name.log 2>&1 & echo $!";
+    Utils::logMessage("Using command: [$cmd]");
+    $pid = shell_exec($cmd);
+    await Control::genStartScriptLog(intval($pid), $name, $cmd);
+  }
+
+  public static async function genStopScript(
+    string $name
+  ): Awaitable<void> {
+    Utils::logMessage("Stopping background script: $name");
+
+    do {
+      // Kill running process
+      $pid = await Control::genScriptPid($name);
+      if ($pid > 0) {
+        Utils::logMessage("Killing $name with PID $pid");
+        exec('kill -9 '.escapeshellarg(strval($pid)));
+      }
+      // Mark process as stopped
+      await Control::genStopScriptLog($pid);
+    } while ($pid > 0); // In case there are multiple instances
+  }
+
   public static async function checkScriptRunning(
     string $name,
   ): Awaitable<bool> {
-    $db = await self::genDb();
-    $host = await Control::genServerAddr();
-    $result = await $db->queryf(
-      'SELECT pid FROM scripts WHERE name = %s AND host = %s AND status = 1',
-      $name,
-      $host,
-    );
-    $status = false;
-    if ($result->numRows() >= 1) {
-      foreach ($result->mapRows() as $row) {
-        $pid = intval(must_have_idx($row, 'pid'));
-        $status = file_exists("/proc/$pid");
-        if ($status === false) {
-          await Control::genStopScriptLog($pid);
-          await Control::genClearScriptLog();
-        }
-      }
-      return $status;
-    } else {
-      return false;
-    }
+    $pid = await self::genScriptPid($name);
+    return $pid !== 0;
   }
 
   public static async function importGame(): Awaitable<bool> {

src/models/Level.php

@@ -1283,24 +1283,12 @@ public static function getBasesResponses(
 
   // Bases processing and scoring.
   public static async function genBaseScoring(): Awaitable<void> {
-    $document_root = must_have_string(Utils::getSERVER(), 'DOCUMENT_ROOT');
-    $cmd =
-      'hhvm -vRepo.Central.Path=/var/run/hhvm/.hhvm.hhbc_bases '.
-      $document_root.
-      '/scripts/bases.php > /dev/null 2>&1 & echo $!';
-    $pid = shell_exec($cmd);
-    await Control::genStartScriptLog(intval($pid), 'bases', $cmd);
+    await Control::genRunScript('bases');
   }
 
   // Stop bases processing and scoring process.
   public static async function genStopBaseScoring(): Awaitable<void> {
-    // Kill running process
-    $pid = await Control::genScriptPid('bases');
-    if ($pid > 0) {
-      exec('kill -9 '.escapeshellarg(strval($pid)));
-    }
-    // Mark process as stopped
-    await Control::genStopScriptLog($pid);
+    await Control::genStopScript('bases');
   }
 
   // Check if a level already exists by type, title and entity.

src/models/Progressive.php

@@ -146,23 +146,11 @@ private static function progressiveFromRow(
 
   // Kick off the progressive scoreboard in the background.
   public static async function genRun(): Awaitable<void> {
-    $document_root = must_have_string(Utils::getSERVER(), 'DOCUMENT_ROOT');
-    $cmd =
-      'hhvm -vRepo.Central.Path=/var/run/hhvm/.hhvm.hhbc_progressive '.
-      $document_root.
-      '/scripts/progressive.php > /dev/null 2>&1 & echo $!';
-    $pid = shell_exec($cmd);
-    await Control::genStartScriptLog(intval($pid), 'progressive', $cmd);
+    await Control::genRunScript('progressive');
   }
 
   // Stop the progressive scoreboard process in the background
   public static async function genStop(): Awaitable<void> {
-    // Kill running process
-    $pid = await Control::genScriptPid('progressive');
-    if ($pid > 0) {
-      exec('kill -9 '.escapeshellarg(strval($pid)));
-    }
-    // Mark process as stopped
-    await Control::genStopScriptLog($pid);
+    await Control::genStopScript('progressive');
   }
 }

src/scripts/autorun.php

@@ -23,6 +23,8 @@
 require_once (__DIR__.'/../models/Announcement.php');
 require_once (__DIR__.'/../models/ActivityLog.php');
 
+Utils::logMessage('Starting autorun');
+
 while (1) {
   \HH\Asio\join(Control::genAutoRun());
 

src/scripts/bases.php

@@ -23,13 +23,16 @@
 
 $conf_game = \HH\Asio\join(Configuration::gen('game'));
 while ($conf_game->getValue() === '1') {
+  Utils::logMessage('Fetching base endpoints');
+
   // Get all active base levels
   $bases_endpoints = array();
   foreach (\HH\Asio\join(Level::genAllActiveBases()) as $base) {
     $endpoint = array(
       'id' => $base->getId(),
       'url' => \HH\Asio\join(Level::genBaseIP($base->getId())),
     );
+    Utils::logMessage("Adding endpoint to call for level ${endpoint['id']}: ${endpoint['url']}");
     array_push($bases_endpoints, $endpoint);
   }
 
@@ -45,10 +48,10 @@
         \HH\Asio\join(Level::genScoreBase($response['id'], $team->getId()));
         //echo "Points\n";
       }
-      //echo "Base(".strval($response['id']).") taken by ".$team_name."\n";
+      Utils::logMessage("Base(".strval($response['id']).") taken by $team_name.");
     } else {
       $code = -1;
-      //echo "Base(".strval($response['id']).") is DOWN\n";
+      Utils::logMessage("Base(".strval($response['id']).") is DOWN");
     }
     \HH\Asio\join(
       Level::genLogBaseEntry(
@@ -60,11 +63,14 @@
   }
   // Wait until next iteration
   $bases_cycle = \HH\Asio\join(Configuration::gen('bases_cycle'));
-  sleep(intval($bases_cycle->getValue()));
+  $sleep_length = $bases_cycle->getValue();
+  Utils::logMessage("Sleeping for $sleep_length seconds");
+  sleep(intval($sleep_length));
 
   // Flush the local cache before the next cycle to ensure the game is still running and the configuration of the bases hasn't changed (the script runs continuously).
   Model::deleteLocalCache();
 
   // Get current game status
   $conf_game = \HH\Asio\join(Configuration::gen('game'));
 }
+Utils::logMessage('Game is no longer running. Shutting down.');

src/scripts/liveimport.php

@@ -597,8 +597,11 @@ public static function debug(
     string $indicator,
     string $message,
   ): void {
+    $msg = "[".date('D M j G:i:s Y')."] [$url] $indicator $message\n";
     if ($debug === true) {
-      print "[".date('D M j G:i:s Y')."] [$url] $indicator $message\n";
+      print $msg;
+    } else {
+      Utils::logMessage($msg);
     }
   }
 }

src/scripts/progressive.php

@@ -12,6 +12,8 @@
 require_once (__DIR__.'/../models/Progressive.php');
 
 while (\HH\Asio\join(Progressive::genGameStatus())) {
+  Utils::logMessage('Progressive scoreboard cycling');
   \HH\Asio\join(Progressive::genTake());
   sleep(\HH\Asio\join(Progressive::genCycle()));
 }
+Utils::logMessage('Game is no longer running. Shutting down.');