Atualmente estou configurando um novo servidor Debian (6.0.5). Eu coloquei o Cacti (0.8.7g) nele ontem e tenho lutado com ele desde então.
Questão inicial
A questão inicial que eu estava observando era que meus gráficos não estavam sendo atualizados. Então, eu verifiquei meu cacti.log
e achei esta mensagem preocupante:
POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
Isso não pode ser bom, certo? Então fui verificar e comecei poller.php
(via %código%). Ele vai bombear um monte de mensagens (que todos parecem com o que eu esperaria) e, em seguida, espere um minuto. Após esse 1 minuto, a seguinte mensagem será repetida:
Waiting on 1 of 1 pollers.
Isso continua por mais 4 minutos até que o processo seja encerrado à força por mais de 298 segundos.
Até aqui tudo bem
Eu continuei por uma boa hora tentando determinar o que o poller ainda pode estar rodando, até que cheguei à conclusão de que simplesmente não é um poller em execução .
Depuração
Eu verifiquei sudo -u www-data php poller.php --force
para ver como 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 do 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é que cheguemos à parte em que ela continua em loop:
Finished: - Started: 1
Waiting on 1 of 1 pollers.
De repente, o valor desapareceu. Por quê? Colocar poller.php
confirma o problema:
NULL
Finished: - Started: 1
Waiting on 1 of 1 pollers.
O valor de retorno é var_dump()
. Como isso pode ser quando se consulta NULL
? ( SELECT COUNT()...
deve sempre retornar uma linha de resultado, não deveria?)
Mais depuração
Então entrei em SELECT COUNT()
e deu uma olhada nesse lib\database.php
. Um pouco de teste confirmado, 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 );
Isto irá produzir
Finished: - Started: 1
array(1) {
["COUNT(*)"]=>
string(1) "2"
}
Waiting on 1 of 1 pollers.
Então, os dados estão lá e podem ser acessados sem problemas, apenas não com o método que o Cacti está usando?
Verifique novamente!
Eu habilitei o log do MySQL para ter certeza de que não estou imaginando coisas. Com certeza, quando a mensagem de erro está em loop, o db_fetch_cell()
lê como se estivesse consultando como louco:
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 nenhum dessas consultas são registradas pelo MySQL. No entanto, quando eu adiciono meu próprio código de consulta de banco de dados, ele aparece muito bem.
cliqueparaampliar
Oquediabosestáacontecendoaqui?
Indomaisfundo...
Concluíqueaconexãocomobancodedadosdeveserperdidaemalgumpontodoprocessoeaadodbsimplesmentenãoseimporta.
Então,apósumpoucodepesquisa,finalmentecoloqueiamensagemdedepuraçãoemcacti.log
,linha529,nafunçãodrivers/adodb-mysql.inc.php
.Euqueriaverquandoaconexãoestáfechada.
Naverdade,eu(finalmente)ativeiadepuraçãodoPHPepercebique_close
foichamadocomumIDdeconexãobooleano(umindicadordeumaconexãointencionalmentefechada).
//returnstrueorfalsefunction_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 ...