diff --git a/cluebot-ng.config.php b/cluebot-ng.config.php index 845b0a7..d0a68f0 100644 --- a/cluebot-ng.config.php +++ b/cluebot-ng.config.php @@ -51,6 +51,9 @@ class Config public static $metrics_port = 9095; // Bots which are spikey in changes and have very large edit counts public static $bot_whitelist = ['InternetArchiveBot', 'AnomieBOT', 'Jevansen']; + // Internal values + public static $mw_mysql_replication_lag_min = 10; + public static $mw_mysql_replication_lag_max = 120; public static function init() { diff --git a/db_functions.php b/db_functions.php index ab50072..9b768d7 100644 --- a/db_functions.php +++ b/db_functions.php @@ -89,6 +89,28 @@ public static function vandalismReverted($edit_id) mysqli_close($cb_mysql); } + public static function getLastVandalismTime() + { + $cb_mysql = self::connect(); + $res = self::runQuery( + $cb_mysql, + 'vandalism_last_timestamp', + 'health_check', + 'SELECT `timestamp` FROM `vandalism` ORDER BY `id` DESC LIMIT 1' + ); + + $timestamp = null; + if ($res !== false) { + $row = mysqli_fetch_assoc($res); + if ($row !== null) { + $timestamp = strtotime($row['timestamp']); + } + } + + mysqli_close($cb_mysql); + return $timestamp; + } + // Returns nothing public static function vandalismRevertBeaten($edit_id, $title, $user, $diff) { diff --git a/globals.php b/globals.php index 908af79..87b84fa 100644 --- a/globals.php +++ b/globals.php @@ -32,5 +32,6 @@ class Globals public static $optin; public static $atime; public static $huggle_wl_reload_time; + public static $replica_lag_check_time; public static $activeChildren = []; } diff --git a/health_check.php b/health_check.php index c16283d..b649cfc 100644 --- a/health_check.php +++ b/health_check.php @@ -21,46 +21,57 @@ * along with ClueBot NG. If not, see . */ - /* Stripped down setup logic */ - date_default_timezone_set('Europe/London'); - include 'vendor/autoload.php'; - $logger = new \Monolog\Logger('cluebotng'); - $logger->pushHandler(new \Monolog\Handler\StreamHandler('php://stderr', \Monolog\Logger::INFO)); +/* Stripped down setup logic */ +date_default_timezone_set('Europe/London'); +include 'vendor/autoload.php'; - require_once 'cluebot-ng.config.php'; - require_once 'api.php'; - require_once 'globals.php'; - require_once 'metric_functions.php'; +$logger = new \Monolog\Logger('cluebotng'); +$logger->pushHandler(new \Monolog\Handler\StreamHandler('php://stderr', \Monolog\Logger::INFO)); + +require_once 'cluebot-ng.config.php'; +require_once 'globals.php'; +require_once 'metric_functions.php'; +require_once 'mysql_functions.php'; +require_once 'db_functions.php'; - /* Configure API access */ Config::init(); Metrics::init(false); -Api::init($logger); +const REPLICATION_LAG_HISTORY_PATH = "/tmp/cluebotng_replica_lag_high_since"; -/* Get container start time */ -$start_time = filemtime("/proc/1"); -Metrics::set('bot_start_time_seconds', (float)$start_time); +/* Get container start time, + * If we have been running for less than 1 hour, then all good (back off) */ +$start_time = (float)filemtime("/proc/1"); +Metrics::set('bot_start_time_seconds', $start_time); -/* If we have been running for less than 1 hour, then all good (back off) */ if ($start_time > (time() - 3600)) { $logger->info('Uptime less than 30min (' . $start_time . ')'); exit(0); } -/* Get our last edit time */ -$usercontribs = Api::$a->usercontribs(Config::$user, 1); -if (count($usercontribs) != 1) { - $logger->error('Failed to find contributions for ' . Config::$user); - exit(1); +/* If we edited within the last 3 hours, then all good (things are working) */ +$last_contribution_time = Db::getLastVandalismTime(); +if ($last_contribution_time !== null && $last_contribution_time > (time() - 10800)) { + $logger->info('Last contribution was within threshold (' . $last_contribution_time . ')'); + exit(0); +} + +/* We haven't edited recently - if the replica is lagging badly, the bot pauses consumption + * on purpose, so that explains it and we shouldn't restart for it */ +$replication_lag = ReplicaDb::getCurrentReplicaLag(); +if ($replication_lag >= Config::$mw_mysql_replication_lag_max) { + $logger->info('No recent edits, but replica lag is high (' . $replication_lag . 's), treating as healthy'); + @file_put_contents(REPLICATION_LAG_HISTORY_PATH, (string)time()); + exit(0); } -$last_contrib_timestamp = $usercontribs[0]['timestamp']; -/* If we edited within the last 3 hours, then all good */ -if (strtotime($last_contrib_timestamp) > (time() - 10800)) { - $logger->info('Last contribution was beyond threshold (' . $last_contrib_timestamp . ')'); +/* Lag is currently normal, but give it an hour to catch up if it was high recently - + * the bot may still be working through the backlog and not have edited yet */ +$last_replication_high_lag_time = @file_get_contents(REPLICATION_LAG_HISTORY_PATH); +if ($last_replication_high_lag_time !== false && (int)$last_replication_high_lag_time > (time() - 3600)) { + $logger->info('No recent edits, but replica lag was high within the last hour, treating as healthy'); exit(0); } /* Otherwise, we need to die */ -$logger->error('Are you death or paradise? ' . $last_contrib_timestamp . ' / ' . $start_time); +$logger->error('Are you death or paradise? ' . $last_contribution_time . ' / ' . $start_time); exit(1); diff --git a/http_feed_functions.php b/http_feed_functions.php index 3c56529..8a74814 100644 --- a/http_feed_functions.php +++ b/http_feed_functions.php @@ -27,6 +27,7 @@ class HttpFeed private static $lastEventId = null; private static $queue = []; private static $running = true; + private static $paused = false; private static $lastCheckpointTime = 0; public static function stream() @@ -41,6 +42,12 @@ public static function stream() $recentAttempts = 0; $handle_interruption_gracefully = false; while (self::$running) { + if (self::$paused) { + sleep(60); + refreshDataTick(); + continue; + } + $recentAttempts++; [$uptime, $handle_interruption_gracefully] = self::connect($handle_interruption_gracefully); if (!self::$running) { @@ -57,6 +64,31 @@ public static function stream() $logger->info('EventStream stopped'); } + public static function isPaused() + { + return self::$paused; + } + + public static function pause() + { + global $logger; + if (!self::$paused) { + $logger->info('HttpFeed paused'); + Metrics::set('bot_stream_pause_status', 1); + self::$paused = true; + } + } + + public static function resume() + { + global $logger; + if (self::$paused) { + $logger->info('HttpFeed resumed'); + Metrics::set('bot_stream_pause_status', 0); + self::$paused = false; + } + } + public static function shutdown() { global $logger; @@ -120,24 +152,25 @@ private static function connect($quiet = false) } refreshDataTick(); Process::dispatchPending(); - } while ($running > 0 && self::$running); + } while ($running > 0 && self::$running && !self::$paused); $uptime = time() - $start_time; - $handle_interruption_gracefully = false; - - $info = curl_multi_info_read($mh); - if ($info !== false && $info['result'] !== CURLE_OK) { - // CURLE_HTTP2_STREAM - the server will close the connection after 15min. - // x-ref: https://wikitech.wikimedia.org/wiki/Event_Platform/EventStreams_HTTP_Service - // - // It appears to happen more often than 15min, so don't gate on time, just re-connect. - // As we are tracking the last ID, we shouldn't miss events, just be slower to see them. - $log_message = 'EventStream hit curl error: ' . curl_strerror($info['result']); - if ($info['result'] === 92) { - $logger->debug($log_message, ['uptime' => $uptime]); - $handle_interruption_gracefully = true; - } else { - $logger->error($log_message, ['uptime' => $uptime]); + $handle_interruption_gracefully = self::$paused ? true : false; + if ($handle_interruption_gracefully !== true) { + $info = curl_multi_info_read($mh); + if ($info !== false && $info['result'] !== CURLE_OK) { + // CURLE_HTTP2_STREAM - the server will close the connection after 15min. + // x-ref: https://wikitech.wikimedia.org/wiki/Event_Platform/EventStreams_HTTP_Service + // + // It appears to happen more often than 15min, so don't gate on time, just re-connect. + // As we are tracking the last ID, we shouldn't miss events, just be slower to see them. + $log_message = 'EventStream hit curl error: ' . curl_strerror($info['result']); + if ($info['result'] === 92) { + $logger->debug($log_message, ['uptime' => $uptime]); + $handle_interruption_gracefully = true; + } else { + $logger->error($log_message, ['uptime' => $uptime]); + } } } diff --git a/metric_functions.php b/metric_functions.php index 83353f3..ab405ee 100644 --- a/metric_functions.php +++ b/metric_functions.php @@ -241,16 +241,24 @@ public static function init($seedMetrics = true): void ); self::registerGauge( 'bot_last_contribution_time', - 'Unix timestamp of the last bot contribution' + 'Unix timestamp of the last bot contribution', + [], + false, ); self::registerGauge( 'bot_start_time_seconds', - 'Unix timestamp of the bot process start time' + 'Unix timestamp of the bot process start time', + [], + false, ); self::registerGauge( 'bot_forks_total', 'Current number of active forked child processes' ); + self::registerGauge( + 'bot_stream_pause_status', + 'Status of the bot stream', + ); // Histograms self::registerHistogram( @@ -275,7 +283,10 @@ private static function seedMetricsStore(): void $logger->debug('Failed to wipe metrics storage: ' . $e->getMessage()); } foreach (self::$definitions as $metric_name => $definition) { - $labelValueSets = empty($definition['labels']) ? [[]] : ($definition['seed'] ?? []); + if (!$definition['seed']) { + continue; + } + $labelValueSets = empty($definition['labels']) ? [[]] : ($definition['seed_label_values'] ?? []); foreach ($labelValueSets as $labelValues) { try { if ($definition['type'] === 'counter') { @@ -299,19 +310,21 @@ private static function registerCounter( string $name, string $help, array $labelNames = [], - array $seedLabelValues = [] + array $seedLabelValues = [], + bool $seed = true, ): void { self::$definitions[$name] = [ 'type' => 'counter', 'help' => $help, 'labels' => $labelNames, - 'seed' => $seedLabelValues, + 'seed_label_values' => $seedLabelValues, + 'seed' => $seed ]; } - private static function registerGauge(string $name, string $help, array $labelNames = []): void + private static function registerGauge(string $name, string $help, array $labelNames = [], $seed = true): void { - self::$definitions[$name] = ['type' => 'gauge', 'help' => $help, 'labels' => $labelNames]; + self::$definitions[$name] = ['type' => 'gauge', 'help' => $help, 'labels' => $labelNames, 'seed' => $seed]; } private static function registerHistogram(string $name, string $help, array $buckets, array $labelNames = []): void diff --git a/misc_functions.php b/misc_functions.php index d21275f..4df3a22 100644 --- a/misc_functions.php +++ b/misc_functions.php @@ -42,6 +42,12 @@ function refreshDataTick() Globals::$tfa = $tfam[1]; } } + + if (!Globals::$replica_lag_check_time || Globals::$replica_lag_check_time + 60 <= time()) { + $logger->debug('Updating replica lag'); + checkReplicaLag(); + Globals::$replica_lag_check_time = time(); + } } function refreshRunFlag() @@ -63,11 +69,34 @@ function loadHuggleWhitelist() } } +function checkReplicaLag() +{ + global $logger; + $replication_lag = ReplicaDb::getCurrentReplicaLag(); + if ($replication_lag >= Config::$mw_mysql_replication_lag_max) { + if (!HttpFeed::isPaused()) { + $logger->warning( + "Replica lag is more than " . Config::$mw_mysql_replication_lag_max . + ", pausing feed: " . $replication_lag + ); + HttpFeed::pause(); + } + return; + } elseif (HttpFeed::isPaused() && $replication_lag <= Config::$mw_mysql_replication_lag_min) { + $logger->notice( + "Replica lag is less than " . Config::$mw_mysql_replication_lag_min . + " seconds, resuming feed: " . $replication_lag + ); + HttpFeed::resume(); + } +} + function doInit() { global $logger; Config::init(); Metrics::init(); + Metrics::set('bot_start_time_seconds', time()); Api::init($logger); if (!Api::$a->login(Config::$user, Config::$pass)) { diff --git a/mysql_functions.php b/mysql_functions.php index 178b3cb..c8978d8 100644 --- a/mysql_functions.php +++ b/mysql_functions.php @@ -246,6 +246,28 @@ private static function getUserDistinctPages($mw_mysql, $userPage) return $data !== null ? $data['count'] : null; } + public static function getCurrentReplicaLag() + { + global $logger; + $mw_mysql = self::connect(); + + $current_lag = 0; + try { + $res = mysqli_query($mw_mysql, 'SELECT lag FROM heartbeat_p.heartbeat WHERE shard = "s1" LIMIT 1'); + if ($res !== false) { + $row = mysqli_fetch_assoc($res); + if ($row !== null) { + $current_lag = $row['lag']; + } + } + } catch (mysqli_sql_exception $e) { + $logger->error("replica lag query returned an error: " . $e->getMessage()); + } + + mysqli_close($mw_mysql); + return $current_lag; + } + public static function getCbData($user = '', $nsid = '', $title = '', $timestamp = '') { $mw_mysql = self::connect();