Warum wartet Cacti immer wieder auf tote Poller-Prozesse?

11

Ich richte gerade einen neuen Debian (6.0.5) Server ein. Ich habe gestern Cacti (0,8,7 g) draufgelegt und kämpfe seitdem damit.

Erstausgabe

Das erste Problem, das ich beobachtete, war, dass meine Grafiken nicht aktualisiert wurden. Also überprüfte ich meine cacti.logund fand dies bezüglich der Nachricht:

POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.

Das kann doch nicht gut sein, oder? Also habe ich nachgesehen und poller.phpmich selbst gestartet (via sudo -u www-data php poller.php --force). Es werden viele Nachrichten herausgepumpt (die alle so aussehen, wie ich es erwarten würde) und dann eine Minute lang hängen bleiben. Nach dieser 1 Minute wird die folgende Meldung wiederholt:

Waiting on 1 of 1 pollers.

Dies dauert weitere 4 Minuten, bis der Vorgang für eine Dauer von mehr als 298 Sekunden zwangsweise beendet wird.

So weit, ist es gut

Ich habe eine gute Stunde lang versucht, festzustellen, welcher Poller noch läuft, bis ich zu dem Schluss kam, dass es einfach keinen laufenden Poller gibt .

Debuggen

Ich habe überprüft poller.php, wie diese Warnung ausgegeben wird und warum. In Zeile 368 ruft Cacti die Anzahl der abgeschlossenen Prozesse aus der Datenbank ab und berechnet anhand dieses Werts, wie viele Prozesse noch ausgeführt werden. Lassen Sie uns diesen Wert sehen!

Ich habe den folgenden Debug-Code hinzugefügt poller.php:

$finished_processes = db_fetch_cell("SELECT count(*) FROM cacti.poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'");
print "Finished: " . $finished_processes . " - Started: " . $started_processes . "\n";

Ergebnis

Dadurch wird innerhalb einer Sekunde nach dem Start Folgendes gedruckt poller.php:

Finished: 0 - Started: 1
Waiting on 1 of 1 pollers.
Finished: 1 - Started: 1

Die Werte werden also gelesen und sind gültig. Bis wir zu dem Teil kommen, in dem es sich immer wieder wiederholt:

Finished:  - Started: 1
Waiting on 1 of 1 pollers.

Plötzlich ist der Wert weg. Warum? Das Einfügen var_dump()bestätigt das Problem:

NULL
Finished:  - Started: 1
Waiting on 1 of 1 pollers.

Der Rückgabewert ist NULL. Wie kann das bei der Abfrage sein SELECT COUNT()...? ( SELECT COUNT()sollte immer eine Ergebniszeile zurückgeben, nicht wahr?)

Mehr Debugging

Also ging ich hinein lib\database.phpund schaute mir das an db_fetch_cell(). Ein bisschen Testen hat bestätigt, dass die Ergebnismenge tatsächlich leer ist.

Also habe ich dort meinen eigenen Datenbank-Abfragecode hinzugefügt, um zu sehen, was das bewirken würde:

$finished_processes = db_fetch_cell("SELECT count(*) FROM poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'");
print "Finished: " . $finished_processes . " - Started: " . $started_processes . "\n";

$mysqli = new mysqli("localhost","cacti","cacti","cacti");
$result = $mysqli->query("SELECT COUNT(*) FROM poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00';");
$row = $result->fetch_assoc();
var_dump( $row );

Dies wird ausgegeben

Finished:  - Started: 1
array(1) {
  ["COUNT(*)"]=>
  string(1) "2"
}
Waiting on 1 of 1 pollers.

Die Daten sind also da und können problemlos abgerufen werden, nur nicht mit der Methode, die Cacti verwendet?

Überprüfen Sie das noch einmal!

Ich habe die MySQL-Protokollierung aktiviert, um sicherzustellen, dass ich mir keine Dinge vorstelle. Sicher genug, wenn die Fehlermeldung geloopt wird, cacti.logliest sich das so, als würde es wie verrückt abgefragt:

06/29/2012 08:44:00 PM - CMDPHP: Poller[0] DEVEL: SQL Cell: "SELECT count(*) FROM cacti.poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'"
06/29/2012 08:44:01 PM - CMDPHP: Poller[0] DEVEL: SQL Cell: "SELECT count(*) FROM cacti.poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'"
06/29/2012 08:44:02 PM - CMDPHP: Poller[0] DEVEL: SQL Cell: "SELECT count(*) FROM cacti.poller_time WHERE poller_id=0 AND end_time>'0000-00-00 00:00:00'"

Aber keine dieser Abfragen werden von MySQL protokolliert. Wenn ich jedoch meinen eigenen Datenbankabfragecode hinzufüge, wird dieser problemlos angezeigt.

Geben Sie hier die Bildbeschreibung ein
klicken um zu vergrößern

Was zum Teufel ist hier los?

Tiefer Graben...

Ich kam zu dem Schluss, dass die Datenbankverbindung irgendwo im Prozess unterbrochen werden muss und es Adodb einfach egal ist.

Nachdem ich ein bisschen herumgegraben hatte, platzierte ich schließlich die Debug-Nachricht in drivers/adodb-mysql.inc.phpZeile 529 in der _closeFunktion. Ich wollte sehen, wann die Verbindung geschlossen ist.

Ich habe tatsächlich (endlich) das PHP-Debugging aktiviert und festgestellt, dass mysql_query()es mit einer booleschen Verbindungs-ID aufgerufen wurde (ein Indikator für eine absichtlich geschlossene Verbindung).

// returns true or false
function _close()
{
    @mysql_close($this->_connectionID);
    echo "!!!! CLOSED !!!!\n";
    debug_print_backtrace();
    $this->_connectionID = false;
}

Was druckt das?

oliver@j27773:/etc/php5/conf.d$ sudo -u www-data php /usr/share/cacti/site/poller.php --force
06/30/2012 01:33:49 AM - POLLER: Poller[0] NOTE: Poller Int: '60', Cron Int: '300', Time Since Last: '61', Max Runtime '298', Poller Runs: '5'
06/30/2012 01:33:49 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/bin/php, ARGS: -q "/usr/share/cacti/site/cmd.php" 0 3]
Finished: 0 - Started: 1
Waiting on 1 of 1 pollers.
Finished: 1 - Started: 1
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_apache_sb_keepalive_100.rrd --template apache_sb_keepalive 1341012829:0
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_apache_reqpersec_95.rrd --template apache_reqpersec 1341012829:.0228409
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_apache_bytesperreq_90.rrd --template apache_bytesperreq 1341012829:13925.7
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_cpu_85.rrd --template cpu 1341012829:1
OK u:0.00 s:0.00 r:1.00
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_hdd_used_80.rrd --template hdd_used:hdd_total 1341012829:924741632:2677886976
OK u:0.00 s:0.00 r:1.00
OK u:0.00 s:0.01 r:1.00
OK u:0.00 s:0.01 r:1.00
06/30/2012 01:33:50 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/lib/cacti/rra/j27773_servers_jiffybox_net_apache_sb_wait_105.rrd --template apache_sb_wait 1341012829:9
OK u:0.00 s:0.01 r:1.00
OK u:0.00 s:0.01 r:1.00
06/30/2012 01:33:50 AM - SYSTEM STATS: Time:1.1261 Method:cmd.php Processes:1 Threads:N/A Hosts:2 HostsPerProcess:2 DataSources:7 RRDsProcessed:6
Loop  Time is: 1.1291718482971
Sleep Time is: 58.867464065552
Total Time is: 1.1325359344482
!!!! CLOSED !!!!
#0  ADODB_mysql->_close() called at [/usr/share/php/adodb/adodb.inc.php:2141]
#1  ADOConnection->Close() called at [/usr/share/cacti/site/lib/database.php:68]
#2  db_close() called at [/usr/share/cacti/site/poller.php:455]
^C06/30/2012 01:33:55 AM - CMDPHP: Poller[0] WARNING: Cacti Master Poller process terminated by user

Und jetzt bin ich zu müde, um das zu untersuchen ...

php debian-squeeze cacti Der Hochstapler
quelle

Antworten:

6

Ich habe etwas weiter nachgeforscht und festgestellt, dass das Schließen der Verbindung zur Datenbank beabsichtigt ist. Die Verbindung sollte für den nächsten Abfragelauf wiederhergestellt werden. Aber es ist nicht so.

Hier ist ein Auszug aus poller.php:

if ($poller_runs_completed < $poller_runs) {
    db_close();
    // Debug message by myself
    echo "RECONNECTING IN " . $sleep_time . "\n";
    usleep($sleep_time * 1000000);
    db_connect_real($database_hostname, $database_username, $database_password, $database_default, $database_type, $database_port);
}

Ich habe auch überprüft db_connect_realund es wird in der Tat nach usleepAbschluss aufgerufen . Dort werde ich also weiter graben.

Vorerst habe ich den Abschnitt folgendermaßen geändert:

if ($poller_runs_completed < $poller_runs) {
    //db_close();
    // Debug message by myself
    echo "RECONNECTING IN " . $sleep_time . "\n";
    usleep($sleep_time * 1000000);
    //db_connect_real($database_hostname, $database_username, $database_password, $database_default, $database_type, $database_port);
}

Jetzt läuft der Poller ohne Warnungen und meine Grafiken werden gezeichnet. Dennoch gibt es immer noch ein Problem. Nicht alle meine Grafiken werden richtig gezeichnet, wie aus dem folgenden Bild ersichtlich ist:

Ein gerendertes Diagramm mit den Ergebnissen der Problemumgehung
klicken um zu vergrößern

Ich nahm an, dass dies daran liegt, dass der Poller für bestimmte Datenquellen zu selten ausgeführt wird. Um das zu lösen, wechselte ich zu Wirbelsäule (was ich sowieso tun wollte) und stellte 4 Threads ein.

Cacti Poller Konfiguration

So weit, ist es gut...

Aktualisieren

Ich habe mich eingehender mit diesem Problem befasst und dachte, ich hätte es behoben. Ich habe angenommen, dass die Verbindung nach dem erneuten Verbindungsversuch des Pollers nicht richtig gespeichert ist.

Mein Versuch, das zu lösen, sah zunächst vielversprechend aus, aber die resultierenden Grafiken waren immer noch fehlerhaft. Das Problem liegt also tiefer.

Die Problemumgehung, die ich zuvor entwickelt und in dieser Antwort vorgestellt habe, funktioniert immer noch einwandfrei. Ich beschloss, keine Zeit mehr in dieses Problem zu investieren und bei der Problemumgehung zu bleiben. Es tut uns leid.

Der Hochstapler
quelle