Dlaczego kaktusy czekają na procesy martwych pyłków?

Obecnie konfiguruję nowy serwer Debian (6.0.5). Położyłem na nim Cacti (0,8 g) i od tego czasu walczę z tym.

Pierwsze wydanie

Pierwszym problemem, który obserwowałem, było to, że moje wykresy nie były aktualizowane. Więc sprawdziłem mój cacti.logi znalazłem ten dotyczący wiadomości:

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

To nie może być dobre, prawda? Więc poszedłem sprawdzić i zacząłem poller.php(via sudo -u www-data php poller.php --force). Wypompuje wiele wiadomości (które wyglądają tak, jakbym się spodziewał), a następnie zawiesi się na minutę. Po upływie 1 minuty zapętli następujący komunikat:

Waiting on 1 of 1 pollers.

Trwa to jeszcze 4 minuty, aż proces zostanie siłą zakończony, aby mógł działać dłużej niż 298 sekund.

Na razie w porządku

Kontynuowałem dobrą godzinę, próbując ustalić, który poller może nadal działać, aż doszedłem do wniosku, że po prostu nie ma działającego pollera .

Debugowanie

Sprawdziłem, poller.phpw jaki sposób wydawane jest to ostrzeżenie i dlaczego. W linii 368 Cacti pobierze liczbę zakończonych procesów z bazy danych i użyje tej wartości do obliczenia liczby uruchomionych procesów. Zobaczmy więc tę wartość!

Dodałem następujący kod debugowania do 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";

Wynik

Spowoduje to wydrukowanie następujących informacji w ciągu sekundy od uruchomienia poller.php:

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

Tak więc wartości są odczytywane i są prawidłowe. Dopóki nie przejdziemy do części, w której ciągle się zapętla:

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

Nagle wartość zniknęła. Dlaczego? Umieszczenie var_dump()tam potwierdza problem:

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

Zwracana wartość to NULL. Jak to może być podczas zapytania SELECT COUNT()...? ( SELECT COUNT()zawsze powinien zwracać jeden wiersz wyniku, prawda?)

Więcej debugowania

Więc weszłam lib\database.phpi rzuciłam na to okiem db_fetch_cell(). Trochę testów potwierdziło, że zestaw wyników jest faktycznie pusty.

Więc dodałem tam własny kod zapytania do bazy danych, aby zobaczyć, co by to zrobiło:

$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 );

To wyjdzie

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

Tak więc dane są dostępne i można je uzyskać bez żadnych problemów, tylko nie przy użyciu metody używanej przez Cacti?

Sprawdź to dwukrotnie!

Włączyłem rejestrowanie MySQL, aby upewnić się, że nic nie wyobrażam. Rzeczywiście, gdy komunikat o błędzie jest zapętlony, cacti.logczyta się tak, jakby pytał jak szalony:

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'"

Ale żadne z tych zapytań nie jest rejestrowane przez MySQL. Jednak po dodaniu własnego kodu zapytania do bazy danych pokazuje się dobrze.

^{Kliknij, aby powiększyć}

Co się tu do cholery dzieje?

Kopać głębiej...

Doszedłem do wniosku, że połączenie z bazą danych musi zostać gdzieś utracone, a adodb po prostu nie ma znaczenia.

Więc po krótkiej analizie w końcu umieściłem komunikat debugowania w drivers/adodb-mysql.inc.phpwierszu 529 w _closefunkcji. Chciałem zobaczyć, kiedy połączenie zostanie zamknięte.

^{Właściwie (w końcu) włączyłem debugowanie PHP i zdałem sobie sprawę, że zostałem mysql_query()wywołany z identyfikatorem połączenia typu boolean (wskaźnik celowo zamkniętego połączenia).}

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

Co to drukuje?

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

A teraz jestem zbyt zmęczony, żeby to zbadać ...

Zagłębiłem się trochę dalej i zdałem sobie sprawę, że zamknięcie połączenia z bazą danych jest celowe. Połączenie powinno zostać przywrócone do następnego uruchomienia odpytywania. Ale tak nie jest.

Oto fragment 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);
}

Sprawdziłem również db_connect_reali tak naprawdę jest wywoływane po usleepzakończeniu. Więc tam będę dalej kopał.

Na razie zmodyfikowałem sekcję w następujący sposób:

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);
}

Teraz poller działa bez ostrzeżeń, a moje wykresy są rysowane. Jednak wciąż istnieje problem. Nie wszystkie moje wykresy są rysowane poprawnie, co widać na poniższym obrazku:

^{Kliknij, aby powiększyć}

Zakładam, że jest to spowodowane zbyt rzadkim uruchomieniem modułu odpytywania dla niektórych źródeł danych. Aby rozwiązać ten problem, przełączyłem się na kręgosłup (co i tak chciałem zrobić) i ustawiłem na używanie 4 wątków.

Na razie w porządku...

Aktualizacja

Zagłębiłem się w ten problem i pomyślałem, że go naprawiłem. Zakładam, że połączenie nie zostało poprawnie zapisane po próbie ponownego połączenia programu poller.

Moja próba rozwiązania tego na początku wyglądała obiecująco, ale uzyskane wykresy były nadal błędne. Problem leży więc głębiej.

Obejście opracowane wcześniej i przedstawione w tej odpowiedzi nadal działa idealnie. Postanowiłem nie inwestować więcej czasu w tę kwestię i pozostać przy obejściu. Przepraszam.