Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions cluebot-ng.config.php
Original file line number Diff line number Diff line change
Expand Up @@ -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()
{
Expand Down
22 changes: 22 additions & 0 deletions db_functions.php
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand Down
1 change: 1 addition & 0 deletions globals.php
Original file line number Diff line number Diff line change
Expand Up @@ -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 = [];
}
61 changes: 36 additions & 25 deletions health_check.php
Original file line number Diff line number Diff line change
Expand Up @@ -21,46 +21,57 @@
* along with ClueBot NG. If not, see <http://www.gnu.org/licenses/>.
*/

/* 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);
65 changes: 49 additions & 16 deletions http_feed_functions.php
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand All @@ -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) {
Expand All @@ -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;
Expand Down Expand Up @@ -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]);
}
}
}

Expand Down
27 changes: 20 additions & 7 deletions metric_functions.php
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand All @@ -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') {
Expand All @@ -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
Expand Down
29 changes: 29 additions & 0 deletions misc_functions.php
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand All @@ -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)) {
Expand Down
22 changes: 22 additions & 0 deletions mysql_functions.php
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
Loading