Cacti (home)ForumsDocumentation
Cacti: offical forums and support
It is currently Sun Mar 26, 2017 10:07 am

All times are UTC - 5 hours




Post new topic Reply to topic  [ 22 posts ]  Go to page Previous  1, 2
Author Message
 Post subject:
PostPosted: Fri Apr 17, 2009 3:06 pm 
Offline
Developer
User avatar

Joined: Tue May 14, 2002 5:08 pm
Posts: 14863
Location: MI, USA
Do you have a few minutes for a gotomeeting today? PM me.

TheWitness

_________________
True understanding begins only when we realize how little we truly understand...

Life is an adventure, let yours begin with Cacti!

Author of MacTrack, Boost, CLog, SpikeKill, Platform RTM, DSStats, maintainer of Spine, lot's of unpublished work and most of Cacti's bugs.
_________________
Official Cacti Documentation
Gandalfs Official Debugging Help
Central Plugin Repository
Central Templates Repository


Top
 Profile  
 
 Post subject:
PostPosted: Wed Apr 22, 2009 8:32 am 
Offline

Joined: Fri Jul 20, 2007 10:24 am
Posts: 23
Hi all,

I was doing some tests with this version and I am getting strange results as well. Spine does not segfault but I see exactly the same gaps in some graphs. What is strange some hosts are almost unaffected (one, maybe two gaps a day) and some of them show only about 20% of graphs.

Logs suggest SNMP timeouts but when I run polling manually everything seems fine for given host.

Below two debug logfile dumps one for successful manual polling from command line and one output from automatic invocation which failed. For automatic one I removed most of the output and left what I thought was important (I have almost 200 hosts in my installation). If you would like to see full dump please let me know.
Host ID in question is 194.

Thank you for any ideas.

#######################
Successful polling:

04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'path_php_binary''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The path_php variable is /usr/bin/php
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'availability_method''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The availability_method variable is 2
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_recovery_count''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The ping_recovery_count variable is 1
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_failure_count''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The ping_failure_count variable is 2
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_method''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The ping_method variable is 2
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_retries''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The ping_retries variable is 1
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_timeout''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The ping_timeout variable is 500
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_perror''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The log_perror variable is 1
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_pwarn''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The log_pwarn variable is 0
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_pstats''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The log_pstats variable is 0
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'max_threads''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The threads variable is 4
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'poller_interval''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The polling interval is 300 seconds
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'concurrent_processes''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The number of concurrent processes is 4
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'script_timeout''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The script timeout is 25
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'php_servers''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The number of php script servers to run is 2
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT action FROM poller_item WHERE action=2 AND host_id BETWEEN 194 AND 194 LIMIT 1'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: StartHost='194', EndHost='194', TotalPHPScripts='0'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The PHP Script Server is Not Required
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'max_get_size''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The Maximum SNMP OID Get Size is 60
04/22/2009 12:37:24 PM - SPINE: Poller[0] SPINE: Initializing Net-SNMP API
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: SNMP Header Version is 5.3.1
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: SNMP Library Version is 5.3.1
04/22/2009 12:37:24 PM - SPINE: Poller[0] SPINE: Initializing PHP Script Server(s)
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT id FROM host WHERE disabled='' AND id BETWEEN 194 AND 194 ORDER BY id'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: Initial Value of Active Threads is 0
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT snmp_port, count(snmp_port) FROM poller_item WHERE host_id=0 AND rrd_next_step < 0 GROUP BY snmp_port'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: 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'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_next_step-300 WHERE host_id=0'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_step-300 WHERE rrd_next_step < 0 and host_id=0'
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[0] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 2
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: 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=194'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] SNMP Result: Host responded to SNMP
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE host SET status='3', status_event_count='0', status_fail_date='2009-04-22 12:20:00', status_rec_date='2009-04-22 12:36:00', status_last_error='Host did not respond to SNMP', min_time='0.000000', max_time='0.000000', cur_time='0.000000', avg_time='0.000000', total_polls='1114', failed_polls='1109', availability='0.4488' WHERE id='194''
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT data_query_id, action, op, assert_value, arg1 FROM poller_reindex WHERE host_id=194'
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] Host has no information for recache.
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT snmp_port, count(snmp_port) FROM poller_item WHERE host_id=194 AND rrd_next_step < 0 GROUP BY snmp_port'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: 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=194 and rrd_next_step <=0 ORDER by snmp_port'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_next_step-300 WHERE host_id=194'
04/22/2009 12:37:24 PM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_step-300 WHERE rrd_next_step < 0 and host_id=194'
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] NOTE: There are '12' Polling Items for this Host
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DEBUG: The POPEN returned the following File Descriptor 7
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3193] SCRIPT: perl /var/www/html/cacti/scripts/ws_apachestats.pl xxx.xxx.xxx.xxx, output: apache_total_hits:772851 apache_total_kbytes:421399 apache_busy_workers:1 apache_idle_workers:79 thread_O:176 threadC:0 threadD:0 threadG:0 threadI:0 threadK:0 threadL:0 threadR:0 threadS:0 threadW:1 thread_W:79 apache_cpuload:3.54877
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3197] SNMP: v3: xxx.xxx.xxx.xxx, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.3, value: 2420905756
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3192] SNMP: v3: xxx.xxx.xxx.xxx, dsname: load_1min, oid: .1.3.6.1.4.1.2021.10.1.3.1, value: 0.00
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3191] SNMP: v3: xxx.xxx.xxx.xxx, dsname: cpu_user, oid: .1.3.6.1.4.1.2021.11.50.0, value: 136762737
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3189] SNMP: v3: xxx.xxx.xxx.xxx, dsname: cpu_nice, oid: .1.3.6.1.4.1.2021.11.51.0, value: 45609
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3190] SNMP: v3: xxx.xxx.xxx.xxx, dsname: cpu_system, oid: .1.3.6.1.4.1.2021.11.52.0, value: 18414355
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DEBUG: The POPEN returned the following File Descriptor 7
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3194] SCRIPT: perl /var/www/html/cacti/scripts/ws_apachestats.pl xxx.xxx.xxx.xxx, output: apache_total_hits:772852 apache_total_kbytes:421399 apache_busy_workers:1 apache_idle_workers:79 thread_O:176 threadC:0 threadD:0 threadG:0 threadI:0 threadK:0 threadL:0 threadR:0 threadS:0 threadW:1 thread_W:79 apache_cpuload:3.54877
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DEBUG: The POPEN returned the following File Descriptor 7
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3195] SCRIPT: perl /var/www/html/cacti/scripts/ws_apachestats.pl xxx.xxx.xxx.xxx, output: apache_total_hits:772853 apache_total_kbytes:421399 apache_busy_workers:1 apache_idle_workers:79 thread_O:176 threadC:0 threadD:0 threadG:0 threadI:0 threadK:0 threadL:0 threadR:0 threadS:0 threadW:1 thread_W:79 apache_cpuload:3.54877
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3197] SNMP: v3: xxx.xxx.xxx.xxx, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.3, value: 229180221
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DS[3196] SNMP: v3: xxx.xxx.xxx.xxx, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.2, value: 2240575772
04/22/2009 12:37:24 PM - SPINE: Poller[0] Host[194] DEBUG: The POPEN returned the following File Descriptor 7
04/22/2009 12:37:25 PM - SPINE: Poller[0] Host[194] DS[3188] SCRIPT: /usr/bin/perl /var/www/html/cacti/scripts/lvm_netstat_tcp.pl xxx.xxx.xxx.xxx 3 public 161 500 xxxxxx xxxxxx, output: established:80 listen:0 timewait:153 timeclose:0 finwait1:0 finwait2:0 synsent:0 synrecv:0 closewait:0
04/22/2009 12:37:25 PM - SPINE: Poller[0] Host[194] DS[3196] SNMP: v3: xxx.xxx.xxx.xxx, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.2, value: 702558900
04/22/2009 12:37:25 PM - SPINE: Poller[0] DEVDBG: SQL:'INSERT INTO poller_output (local_data_id, rrd_name, time, output) VALUES (3197,'traffic_out','2009-04-22 12:37:24','2420905756'),(3193,'','2009-04-22 12:37:24','apache_total_hits:772851 apache_total_kbytes:421399 apache_busy_workers:1 apache_idle_workers:79 thread_O:176 threadC:0 threadD:0 threadG:0 threadI:0 threadK:0 threadL:0 threadR:0 threadS:0 threadW:1 thread_W:79 apache_cpuload:3.54877'),(3192,'load_1min','2009-04-22 12:37:24','0.00'),(3191,'cpu_user','2009-04-22 12:37:24','136762737'),(3189,'cpu_nice','2009-04-22 12:37:24','45609'),(3190,'cpu_system','2009-04-22 12:37:24','18414355'),(3197,'traffic_in','2009-04-22 12:37:24','229180221'),(3194,'','2009-04-22 12:37:24','apache_total_hits:772852 apache_total_kbytes:421399 apache_busy_workers:1 apache_idle_workers:79 thread_O:176 threadC:0 threadD:0 threadG:0 threadI:0 threadK:0 threadL:0 threadR:0 threadS:0 threadW:1 thread_W:79 apache_cpuload:3.54877'),(3195,'','2009-04-22 12:37:24','apache_total_hits:772853 apache_total_kbytes:421399 apache_busy_worke'
04/22/2009 12:37:25 PM - SPINE: Poller[0] Host[194] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
04/22/2009 12:37:25 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
04/22/2009 12:37:25 PM - SPINE: Poller[0] DEVDBG: SQL:'replace into settings (name,value) values ('date',NOW())'
04/22/2009 12:37:25 PM - SPINE: Poller[0] DEVDBG: SQL:'insert into poller_time (poller_id, start_time, end_time) values (0, NOW(), NOW())'
04/22/2009 12:37:25 PM - SPINE: Poller[0] DEBUG: Thread Cleanup Complete
04/22/2009 12:37:25 PM - SPINE: Poller[0] DEBUG: PHP Script Server Pipes Closed
04/22/2009 12:37:25 PM - SPINE: Poller[0] DEBUG: Allocated Variable Memory Freed
04/22/2009 12:37:25 PM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
04/22/2009 12:37:25 PM - SPINE: Poller[0] Time: 0.6647 s, Threads: 4, Hosts: 2

################################################################
Failed automatic polling

04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'config_arrays'"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'config_settings'"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'valid_host_fields'"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'config_form'"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'config_insert'"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'poller_top'"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Cell: "SELECT COUNT(*) FROM poller_item WHERE rrd_next_step<=0"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT host_id, COUNT(*) AS data_sources FROM poller_item WHERE rrd_next_step<=0 GROUP BY host_id ORDER BY host_id"
04/22/2009 12:35:01 PM - POLLER: Poller[0] NOTE: Poller Int: '300', Cron Int: '300', Time Since Last: '300', Max Runtime '298', Poller Runs: '1'
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Exec: "REPLACE INTO settings (name,value) VALUES ('poller_lastrun',1240400101)"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT id FROM host WHERE disabled = '' ORDER BY id"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Exec: "REPLACE INTO settings (name,value) VALUES ('path_webroot','/var/www/html/cacti')"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Exec: "TRUNCATE TABLE poller_time"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT local_data_id, rrd_name FROM poller_output"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'poller_command_args'"
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'path_php_binary''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The path_php variable is /usr/bin/php
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'availability_method''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The availability_method variable is 2
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_recovery_count''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_recovery_count variable is 1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_failure_count''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_failure_count variable is 2
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_method''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_method variable is 2
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_retries''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_retries variable is 1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_timeout''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_timeout variable is 500
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_perror''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The log_perror variable is 1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_pwarn''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The log_pwarn variable is 0
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_pstats''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The log_pstats variable is 0
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'max_threads''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The threads variable is 4
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'poller_interval''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The polling interval is 300 seconds
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'concurrent_processes''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The number of concurrent processes is 4
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'script_timeout''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The script timeout is 25
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'php_servers''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The number of php script servers to run is 2
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT action FROM poller_item WHERE action=2 AND host_id BETWEEN 0 AND 49 LIMIT 1'
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: StartHost='0', EndHost='49', TotalPHPScripts='1'
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The PHP Script Server is Required
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'max_get_size''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The Maximum SNMP OID Get Size is 60
04/22/2009 12:35:01 PM - SPINE: Poller[0] SPINE: Initializing Net-SNMP API
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: SNMP Header Version is 5.3.1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: SNMP Library Version is 5.3.1
04/22/2009 12:35:01 PM - SPINE: Poller[0] SPINE: Initializing PHP Script Server(s)
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: SS[0] PHP Script Server Routine Starting
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: SS[0] PHP Script Server About to FORK Child Process
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: SS[0] PHP Script Server Child FORK Success
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'path_php_binary''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The path_php variable is /usr/bin/php
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'availability_method''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The availability_method variable is 2
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_recovery_count''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_recovery_count variable is 1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_failure_count''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_failure_count variable is 2
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_method''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_method variable is 2
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_retries''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_retries variable is 1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'ping_timeout''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The ping_timeout variable is 500
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_perror''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The log_perror variable is 1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_pwarn''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The log_pwarn variable is 0
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'log_pstats''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The log_pstats variable is 0
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'max_threads''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The threads variable is 4
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'poller_interval''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The polling interval is 300 seconds
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'concurrent_processes''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The number of concurrent processes is 4
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'script_timeout''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The script timeout is 25
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'php_servers''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The number of php script servers to run is 2
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT action FROM poller_item WHERE action=2 AND host_id BETWEEN 50 AND 95 LIMIT 1'
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: StartHost='50', EndHost='95', TotalPHPScripts='0'
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The PHP Script Server is Not Required
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT value FROM settings WHERE name = 'max_get_size''
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The Maximum SNMP OID Get Size is 60
04/22/2009 12:35:01 PM - SPINE: Poller[0] SPINE: Initializing Net-SNMP API
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: SNMP Header Version is 5.3.1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: SNMP Library Version is 5.3.1
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'config_arrays'"
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'config_settings'"
04/22/2009 12:35:01 PM - SPINE: Poller[0] SPINE: Initializing PHP Script Server(s)
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT id FROM host WHERE disabled='' AND id BETWEEN 50 AND 95 ORDER BY id'
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: Initial Value of Active Threads is 0
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
04/22/2009 12:35:01 PM - CMDPHP: Poller[0] DEVEL: SQL Assoc: "SELECT name, file, function FROM plugin_hooks WHERE status = 1 AND hook = 'valid_host_fields'"
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT snmp_port, count(snmp_port) FROM poller_item WHERE host_id=0 AND rrd_next_step < 0 GROUP BY snmp_port'
04/22/2009 12:35:01 PM - SPINE: Poller[0] DEVDBG: 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'

<removed lines>

04/22/2009 12:35:07 PM - SPINE: Poller[0] DEVDBG: 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=194'
<removed 1200 lines>
04/22/2009 12:35:10 PM - SPINE: Poller[0] Host[194] SNMP Result: Host did not respond to SNMP
04/22/2009 12:35:10 PM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE host SET status='1', status_event_count='4', status_fail_date='2009-04-22 12:20:00', status_rec_date='2009-04-22 12:12:00', status_last_error='Host did not respond to SNMP', min_time='0.000000', max_time='0.000000', cur_time='0.000000', avg_time='0.000000', total_polls='1112', failed_polls='1109', availability='0.2698' WHERE id='194''
04/22/2009 12:35:10 PM - SPINE: Poller[0] DEVDBG: SQL:'SELECT snmp_port, count(snmp_port) FROM poller_item WHERE host_id=194 AND rrd_next_step < 0 GROUP BY snmp_port'
04/22/2009 12:35:10 PM - SPINE: Poller[0] DEVDBG: 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=194 and rrd_next_step <=0 ORDER by snmp_port'
04/22/2009 12:35:10 PM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_next_step-300 WHERE host_id=194'
04/22/2009 12:35:10 PM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE poller_item SET rrd_next_step=rrd_step-300 WHERE rrd_next_step < 0 and host_id=194'
04/22/2009 12:35:10 PM - SPINE: Poller[0] Host[194] NOTE: There are '12' Polling Items for this Host
04/22/2009 12:35:10 PM - SPINE: Poller[0] Host[194] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
04/22/2009 12:35:10 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
04/22/2009 12:35:10 PM - SPINE: Poller[0] DEVDBG: SQL:'replace into settings (name,value) values ('date',NOW())'


Top
 Profile  
 
 Post subject:
PostPosted: Wed Apr 22, 2009 9:03 am 
Offline
Cacti Guru User
User avatar

Joined: Thu Sep 16, 2004 5:53 am
Posts: 5055
Location: United Kingdom
Just had a quick try of this version along with my newly updated 0.8.7d install, and...

Code:
04/22/2009 02:37:09 PM - SYSTEM STATS: Time:127.9749 Method:cmd.php Processes:4 Threads:N/A Hosts:237 HostsPerProcess:60 DataSources:11943 RRDsProcessed:4610
04/22/2009 02:45:00 PM - SYSTEM STATS: Time:298.8121 Method:spine Processes:4 Threads:15 Hosts:237 HostsPerProcess:60 DataSources:11943 RRDsProcessed:1071
04/22/2009 02:50:00 PM - SYSTEM STATS: Time:298.8212 Method:spine Processes:4 Threads:15 Hosts:237 HostsPerProcess:60 DataSources:11943 RRDsProcessed:2372


I'll hopefully have some time to work through the logs and see what is failing later.

_________________
Weathermap 0.98 is out! & QuickTree 0.2. Superlinks is over there now.
Some Other Cacti tweaks, including strip-graphs, icons and snmp/netflow stuff.
(Let me know if you have UK DevOps or Network Ops opportunities, too!)


Top
 Profile  
 
 Post subject:
PostPosted: Fri Apr 24, 2009 11:39 am 
Offline
Cacti User
User avatar

Joined: Tue Nov 01, 2005 2:10 pm
Posts: 72
Location: Lafayette, LA
TheWitness, I have a ton of core dumps to play with now. Just let me know when you have time to take a look.


Top
 Profile  
 
 Post subject:
PostPosted: Fri May 01, 2009 2:16 pm 
Offline
Cacti User
User avatar

Joined: Tue Aug 24, 2004 5:02 pm
Posts: 371
Location: San Francisco, CA
I'm getting a "Bus Error (Spine thread)" with this, intermittently.

I can reproduce it on multiple hosts (at first I thought it was bad memory)..

It doesn't happen all the time, it seems to only happen on runs that include hosts from the end of my host id range, is reproducible with as few as one polled host; but it does not matter which host, as long as it's near the end of the host list.

Truss outputs:
Code:
truss: get_struct 0x3900000000: Bad address


Running this gets the error, most of the time:
Code:
/usr/local/spine/bin/spine --stdout --poller=2 --conf=/usr/local/spine/etc/spine.conf --verbosity=5 --first=1432 --last=1432


I can change 1432 to any number in the last 50 or so and get the error within the first few runs. I noticed that the output if it succeeds has the Hosts count as one higher than it should be (there's some logic in the code for excluding host id 0, which seems irrelevant here...) I tried chasing that down, but it does not seem to be related to this.

If you have advice on what to do next, I'm happy to persue this.

_________________
FreeBSD/RHEL
cacti-0.8.7i, spine 0.8.7i, PIA 3.1+boost 5.1
MySQL 5.5/InnoDB
RRDtool 1.2.27, PHP 5.1.6


Top
 Profile  
 
 Post subject:
PostPosted: Fri May 01, 2009 3:43 pm 
Offline
Developer
User avatar

Joined: Tue May 14, 2002 5:08 pm
Posts: 14863
Location: MI, USA
Sorry all. I have been in disposed. If you pull SVN, you will find the fix to this issue. Also, read the README. I have changed the default popen to nifty again due to timeout issues with standard popen.

I believe you will find SVN quite stable.

Regards,

Larry

_________________
True understanding begins only when we realize how little we truly understand...

Life is an adventure, let yours begin with Cacti!

Author of MacTrack, Boost, CLog, SpikeKill, Platform RTM, DSStats, maintainer of Spine, lot's of unpublished work and most of Cacti's bugs.
_________________
Official Cacti Documentation
Gandalfs Official Debugging Help
Central Plugin Repository
Central Templates Repository


Top
 Profile  
 
 Post subject:
PostPosted: Fri May 01, 2009 6:19 pm 
Offline
Cacti User
User avatar

Joined: Tue Aug 24, 2004 5:02 pm
Posts: 371
Location: San Francisco, CA
Awesome. SVN appears to solve my issues.

_________________
FreeBSD/RHEL
cacti-0.8.7i, spine 0.8.7i, PIA 3.1+boost 5.1
MySQL 5.5/InnoDB
RRDtool 1.2.27, PHP 5.1.6


Top
 Profile  
 
Display posts from previous:  Sort by  
Post new topic Reply to topic  [ 22 posts ]  Go to page Previous  1, 2

All times are UTC - 5 hours


Who is online

Users browsing this forum: No registered users and 2 guests


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot post attachments in this forum

Search for:
Jump to:  

Protected by Anti-Spam ACP Powered by phpBB © 2000, 2002, 2005, 2007 phpBB Group