Switched from CMD.PHP to Spine, now timeout problems

[RHServices]

I recently switched my cacti install from CMD to Spine. I initially had problems with buffer overflows and have since downloaded the version of Spine from the webpage (My old one said 0.8.7B and so does this one... recompile must have helped). Solved that problem.

I thought that would solve the problem I had previously which was:

06/29/2008 11:55:01 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
06/29/2008 11:55:01 PM - SYSTEM STATS: Time:299.7430 Method:spine Processes:4 Threads:7 Hosts:2 HostsPerProcess:1 DataSources:12 RRDsProcessed:6


I've only got two hosts with 12 data sources... This thing shouldn't be timing out.

A spine -V 5 comes out just fine in under a second. Here's the output of that... Why would Spine timeout when executed from poller.php? I recently set my php.ini memory size to 256M and that didn't help, either.

Running on CentOS.


[root@mgmt log]# spine -V 5
SPINE: Using spine config file [/etc/spine.conf]
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'path_webroot''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'path_cactilog''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The path_php_server variable is /var/www/cacti/script_server.php
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The path_cactilog variable is /var/www/cacti/log/cacti.log
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'log_destination''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The log_destination variable is 1 (FILE)
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'path_php_binary''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The path_php variable is /usr/bin/php
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'availability_method''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The availability_method variable is 0
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_recovery_count''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The ping_recovery_count variable is 3
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_failure_count''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The ping_failure_count variable is 2
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_method''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The ping_method variable is 1
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_retries''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The ping_retries variable is 1
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'ping_timeout''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The ping_timeout variable is 400
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'log_perror''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The log_perror variable is 1
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'log_pwarn''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The log_pwarn variable is 0
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'log_pstats''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The log_pstats variable is 0
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'max_threads''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The threads variable is 7
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'poller_interval''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The polling interval is 300 seconds
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'concurrent_processes''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The number of concurrent processes is 4
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'script_timeout''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The script timeout is 25
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'php_servers''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The number of php script servers to run is 7
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT action FROM poller_item WHERE action=2 LIMIT 1'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: StartHost='-1', EndHost='-1', TotalPHPScripts='0'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The PHP Script Server is Not Required
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT value FROM settings WHERE name = 'max_get_size''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The Maximum SNMP OID Get Size is 10
06/29/2008 11:59:06 PM - SPINE: Poller[0] Version 0.8.7b starting
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: MySQL is Thread Safe!
06/29/2008 11:59:06 PM - SPINE: Poller[0] SPINE: Initializing Net-SNMP API
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SNMP Header Version is 5.3.1
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SNMP Library Version is 5.3.1
06/29/2008 11:59:06 PM - SPINE: Poller[0] SPINE: Initializing PHP Script Server(s)
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT id FROM host WHERE disabled='' ORDER BY id'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: Initial Value of Active Threads is 0
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT snmp_port, count(snmp_port) FROM poller_item WHERE host_id=0 AND rrd_next_step < 0 GROUP BY snmp_port'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT action, hostname, snmp_community, snmp_version, snmp_username, snmp_password, rrd_name, rrd_path, arg1, arg2, arg3, local_data_id, rrd_num, snmp_port, snmp_timeout, snmp_auth_protocol, snmp_priv_passphrase, snmp_priv_protocol, snmp_context FROM poller_item WHERE host_id=0 and rrd_next_step <=0 ORDER by snmp_port'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 2
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_next_step-300 WHERE host_id=0'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_step-300 WHERE rrd_next_step < 0 and host_id=0'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT id, hostname, snmp_community, snmp_version, snmp_username, snmp_password, snmp_auth_protocol, snmp_priv_passphrase, snmp_priv_protocol, snmp_context, snmp_port, snmp_timeout, max_oids, availability_method, ping_method, ping_port, ping_timeout, ping_retries, status, status_event_count, status_fail_date, status_rec_date, status_last_error, min_time, max_time, cur_time, avg_time, total_polls, failed_polls, availability FROM host WHERE id=6'
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[0] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] No Host Availability Method Selected
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'UPDATE host SET status='3', status_event_count='0', status_fail_date='0000-00-00 00:00:00', status_rec_date='0000-00-00 00:00:00', status_last_error='', min_time='0.000000', max_time='0.000000', cur_time='0.000000', avg_time='0.000000', total_polls='5', failed_polls='0', availability='100.0000' WHERE id='6''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT data_query_id, action, op, assert_value, arg1 FROM poller_reindex WHERE host_id=6'
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] RECACHE: Processing 1 items in the auto reindex cache for '66.112.214.13'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'UPDATE poller_reindex SET assert_value='17939451' WHERE host_id='6' AND data_query_id='1' and arg1='.1.3.6.1.2.1.1.3.0''
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT snmp_port, count(snmp_port) FROM poller_item WHERE host_id=6 AND rrd_next_step < 0 GROUP BY snmp_port'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'SELECT action, hostname, snmp_community, snmp_version, snmp_username, snmp_password, rrd_name, rrd_path, arg1, arg2, arg3, local_data_id, rrd_num, snmp_port, snmp_timeout, snmp_auth_protocol, snmp_priv_passphrase, snmp_priv_protocol, snmp_context FROM poller_item WHERE host_id=6 and rrd_next_step <=0 ORDER by snmp_port'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_next_step-300 WHERE host_id=6'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_step-300 WHERE rrd_next_step < 0 and host_id=6'
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[20] SNMP: v1: 66.112.214.13, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.8, value: 1618309
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[20] SNMP: v1: 66.112.214.13, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.8, value: 43951197
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[18] SNMP: v1: 66.112.214.13, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.6, value: 31843369
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[19] SNMP: v1: 66.112.214.13, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.7, value: 6361008
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[19] SNMP: v1: 66.112.214.13, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.7, value: 30065946
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[16] SNMP: v1: 66.112.214.13, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.4, value: 1227225148
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[17] SNMP: v1: 66.112.214.13, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.5, value: 20237
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[17] SNMP: v1: 66.112.214.13, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.5, value: 22685834
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[18] SNMP: v1: 66.112.214.13, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.6, value: 27134900
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[15] SNMP: v1: 66.112.214.13, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.3, value: 1261646259
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[15] SNMP: v1: 66.112.214.13, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.3, value: 527036572
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DS[16] SNMP: v1: 66.112.214.13, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.4, value: 492459939
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'INSERT INTO poller_output (local_data_id, rrd_name, time, output) VALUES (20,'traffic_in','2008-06-29 23:59:06','1618309'),(20,'traffic_out','2008-06-29 23:59:06','43951197'),(18,'traffic_out','2008-06-29 23:59:06','31843369'),(19,'traffic_in','2008-06-29 23:59:06','6361008'),(19,'traffic_out','2008-06-29 23:59:06','30065946'),(16,'traffic_out','2008-06-29 23:59:06','1227225148'),(17,'traffic_in','2008-06-29 23:59:06','20237'),(17,'traffic_out','2008-06-29 23:59:06','22685834'),(18,'traffic_in','2008-06-29 23:59:06','27134900'),(15,'traffic_in','2008-06-29 23:59:06','1261646259'),(15,'traffic_out','2008-06-29 23:59:06','527036572'),(16,'traffic_in','2008-06-29 23:59:06','492459939')'
06/29/2008 11:59:06 PM - SPINE: Poller[0] Host[6] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'replace into settings (name,value) values ('date',NOW())'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: SQL:'insert into poller_time (poller_id, start_time, end_time) values (0, NOW(), NOW())'
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: Thread Cleanup Complete
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: PHP Script Server Pipes Closed
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: Allocated Variable Memory Freed
06/29/2008 11:59:06 PM - SPINE: Poller[0] SPINE: Net-SNMP API Shutdown Completed
06/29/2008 11:59:06 PM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
06/29/2008 11:59:06 PM - SPINE: Poller[0] Time: 0.0849 s, Threads: 7, Hosts: 2

[TheWitness]

What about your spine path under settings->paths?

TheWitness

[tamnais]

I have the same problem, with Cacti 0.8.7b and spine 0.8.7a (last available stable build from http://www.cacti.net/spine_download.php)

06/30/2008 01:10:05 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
06/30/2008 01:10:05 PM - SYSTEM STATS: Time:299.6448 Method:spine Processes:1 Threads:1 Hosts:4 HostsPerProcess:4 DataSources:12 RRDsPr
ocessed:0

Running on Solaris 9 and I have also noticed, that php process, along with clidren up to rrdtool just hangs around, doing nothing (checked with truss -p <pid>).

| | \-+- 17506 root sh -c /usr/local/bin/php /u/httpd/htdocs1/cacti/poller.php
| | \-+- 17507 root /usr/local/bin/php /u/httpd/htdocs1/cacti/poller.php
| | \-+- 17512 root sh -c /opt/csw/bin/rrdtool -
| | \--- 17513 root /opt/csw/bin/rrdtool -

Eventually, I have to kill the php process manually.

Switched back to cmd.php and polling works ok. And running spine manually also works ok. Any ideas?

[RHServices]

/var/www/cacti/poller.php is my poller path

[root@mgmt cacti]# ls -la poller.php
-rw-r--r-- 1 root root 15178 Jun 30 00:16 poller.php

[johnzw]

I have the same problem with RHServices, and do you install CentOS in a virtual machine platform?