Por que os Cacti continuam esperando processos mortos de pesquisas?

11

Atualmente, estou configurando um novo servidor Debian (6.0.5). Coloquei Cacti (0.8.7g) nele ontem e venho lutando com ele desde então.

Questão inicial

O problema inicial que eu estava observando era que meus gráficos não estavam sendo atualizados. Então eu verifiquei o meu cacti.loge encontrei esta mensagem relativa:

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

Isso não pode ser bom, certo? Então eu fui checar e poller.phpme iniciei (via sudo -u www-data php poller.php --force). Ele distribuirá muitas mensagens (todas parecidas com o que eu esperaria) e depois ficará suspenso por um minuto. Após esse minuto, ele repetirá a seguinte mensagem:

Waiting on 1 of 1 pollers.

Isso continua por mais 4 minutos até que o processo seja encerrado com força por mais de 298s.

Por enquanto, tudo bem

Passei uma boa hora tentando determinar qual pesquisador ainda poderia estar em execução, até chegar à conclusão de que simplesmente não há pesquisador em execução .

Depuração

Eu verifiquei poller.phppara ver como esse aviso é emitido e por quê. Na linha 368, o Cacti recuperará o número de processos concluídos do banco de dados e usará esse valor para calcular quantos processos ainda estão em execução. Então, vamos ver esse valor!

Eu adicionei o seguinte código de depuração em 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";

Resultado

Isso imprimirá o seguinte dentro de um segundo após o início poller.php:

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

Portanto, os valores estão sendo lidos e são válidos. Até chegarmos à parte em que ele continua em loop:

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

De repente, o valor se foi. Por quê? Colocar var_dump()lá confirma o problema:

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

O valor de retorno é NULL. Como pode ser isso ao consultar SELECT COUNT()...? ( SELECT COUNT()sempre deve retornar uma linha de resultado, não deveria?)

Mais depuração

Então eu entrei lib\database.phpe dei uma olhada nisso db_fetch_cell(). Um pouco de teste confirmou que o conjunto de resultados está realmente vazio.

Então, adicionei meu próprio código de consulta ao banco de dados para ver o que isso faria:

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

Isso produzirá

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

Portanto, os dados estão lá e podem ser acessados ​​sem problemas, apenas não com o método que o Cacti está usando?

Verifique isso!

Habilitei o log do MySQL para ter certeza de que não estou imaginando coisas. Com certeza, quando a mensagem de erro é repetida, as cacti.logleituras são como se estivessem perguntando como loucas:

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

Mas nenhuma dessas consultas é registrada pelo MySQL. No entanto, quando adiciono meu próprio código de consulta ao banco de dados, ele aparece muito bem.

insira a descrição da imagem aqui
Clique para ampliar

O que diabos está acontecendo aqui?

Indo mais fundo ...

Concluí que a conexão com o banco de dados deve ser perdida em algum lugar do processo e o adodb simplesmente não se importa.

Então, depois de um pouco de pesquisa, finalmente coloquei a mensagem de depuração na drivers/adodb-mysql.inc.phplinha 529 na _closefunção. Eu queria ver quando a conexão está fechada.

Na verdade (finalmente) ativei a depuração do PHP e percebi que mysql_query()era chamado com um ID de conexão booleana (um indicador de uma conexão intencionalmente fechada).

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

O que isso imprime?

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

E agora estou cansado demais para investigar isso ...

php debian-squeeze cacti Der Hochstapler
fonte

Respostas:

6

Eu investiguei um pouco mais e percebi que o fechamento da conexão com o banco de dados é intencional. A conexão deve ser restabelecida para a próxima execução da pesquisa. Mas não é.

Aqui está um trecho de 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);
}

Eu também verifiquei db_connect_reale é, de fato, chamado após a usleepconclusão. Então é aí que eu vou continuar cavando.

Por enquanto, modifiquei a seção assim:

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

Agora, o pesquisador é executado sem nenhum aviso e meus gráficos estão sendo desenhados. No entanto, ainda há um problema. Nem todos os meus gráficos estão sendo desenhados corretamente, como pode ser visto na imagem a seguir:

Um gráfico renderizado mostrando os resultados da solução alternativa
Clique para ampliar

Supus que isso se deva ao fato de o poller ser executado muito raramente em determinadas fontes de dados. Para resolver isso, mudei para a coluna (o que eu queria fazer de qualquer maneira) e configurei para usar 4 threads.

Configuração do poller do Cacti

Por enquanto, tudo bem...

Atualizar

Analisei mais profundamente esse problema e pensei que o havia corrigido. Presumi que a conexão não foi armazenada corretamente após a tentativa de reconexão do pesquisador.

Minha tentativa de resolver isso parecia promissora no começo, mas os gráficos resultantes ainda estavam com defeito. Portanto, o problema está mais profundo.

A solução alternativa que desenvolvi anteriormente e apresentei nesta resposta ainda funciona perfeitamente. Decidi não investir mais tempo nessa questão e ficar com a solução alternativa. Desculpa.

Der Hochstapler
fonte