Constant Recaching Loop

[rdege]

Code: Select all

# perl /var/www/html/cacti-0.8.7e/scripts/query_unix_partitions.pl num_indexes
3

[gandalf]

You're running cmd.php as a poller?
Are you able to upgrade to 087g beta1 on a test system. I made some more changes to cmd.php to cover that issue and added some more log messages
R.

[rdege]

I'm actually using spine as my poller:

# /usr/local/spine/bin/spine -h
SPINE 0.8.7e Copyright 2002-2009 by The Cacti Group

If you still want me to refresh my test server with 087g beta1, just lemme know.

-Rob

[gandalf]

I'm quite sure, that "num_indexes" is not yet implemented by spine. This question goes to Larry "TheWitness" Adams
R.

[rdege]

This is quite interesting. I never thought that the poller itself would be the culprit. I'm going to setup the test server so that it uses cmd.php instead of spine and see if that resolves the problem.

I'll post my findings.

Thanks for all the help so far =)

[gandalf]

This is quite interesting. I never thought that the poller itself would be the culprit. I'm going to setup the test server so that it uses cmd.php instead of spine and see if that resolves the problem.

I'll post my findings.

Thanks for all the help so far =)

That would indeed be very helpful
R.

[TheWitness]

This is fixed, but you need to be on "g" of Cacti and Spine.

TheWitness

[gandalf]

This is fixed, but you need to be on "g" of Cacti and Spine.

TheWitness

Good news!
R.

[TheWitness]

I'm going to do some validation this morning before I conduct Cacti training this afternoon

TheWitness

[rdege]

For some unknown reason, when I copied my cacti environment over to my test server, one of the two re-caching problems disappeared. It still persists on the live server, but is gone on the test. The only difference that I can see is that the test server is monitoring less devices than the live server (I disabled a bunch in the Device section).

On the test server:

Code: Select all

06/11/2010 02:15:08 PM - PCOMMAND: Poller[0] Host[148] WARNING: Recache Event Detected for Host 

On the live server:

Code: Select all

06/11/2010 02:15:19 PM - PCOMMAND: Poller[0] Host[18] WARNING: Recache Event Detected for Host
06/11/2010 02:15:18 PM - PCOMMAND: Poller[0] Host[148] WARNING: Recache Event Detected for Host 

Just to reiterate:
Host 18 is a Windows 2003 server that is a VM. SNMP - Get Mounted Partitions is set to Uptime Goes Backwards
Host 148 is a Barracuda Machine. Unix - Get Mounted Partitions is set to Index Count Changed.

Using the cmd.php on the test server appears to have resolved the recache problem. I no longer see the warning messages in the log. If I toggle back to spine, then the message reappears.

[TheWitness]

On the box with issue run qthe following

Code: Select all

./spine -V 5 -R -f <hostid> -l <hostid>

On the host in question. Post results.

TheWitness

[rdege]

I added -C /usr/local/spine/etc/spine.conf to the command line, since spine complained about a missing config file. Here are the results:

Code: Select all

# /usr/local/spine/bin/spine -V 5 -R -f 148 -l 148 -C /usr/local/spine/etc/spine.conf
SPINE: Using spine config file [/usr/local/spine/etc/spine.conf]
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The path_php_server variable is /var/www/html/cacti-0.8.7e/script_server.php
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The path_cactilog variable is /var/www/html/cacti/log/cacti.log
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The log_destination variable is 1 (FILE)
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The path_php variable is /usr/local/php-5.2.5/bin/php
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The availability_method variable is 2
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The ping_recovery_count variable is 3
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The ping_failure_count variable is 2
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The ping_method variable is 2
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The ping_retries variable is 1
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The ping_timeout variable is 400
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The snmp_retries variable is 3
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The log_perror variable is 1
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The log_pwarn variable is 1
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The boost_redirect variable is 0
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The log_pstats variable is 1
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The threads variable is 15
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The polling interval is 300 seconds
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The number of concurrent processes is 3
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The script timeout is 25
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The number of php script servers to run is 1
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: StartHost='148', EndHost='148', TotalPHPScripts='0'
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The PHP Script Server is Not Required
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The Maximum SNMP OID Get Size is 10
06/14/2010 03:23:56 PM - SPINE: Poller[0] Version 0.8.7e starting
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: MySQL is Thread Safe!
06/14/2010 03:23:56 PM - SPINE: Poller[0] SPINE: Initializing Net-SNMP API
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: SNMP Header Version is 5.1.2
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: SNMP Library Version is 5.1.2
06/14/2010 03:23:56 PM - SPINE: Poller[0] SPINE: Initializing PHP Script Server(s)
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: Initial Value of Active Threads is 0
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[0] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 2
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
06/14/2010 03:23:56 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] SNMP Result: Host responded to SNMP
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] RECACHE: Processing 3 items in the auto reindex cache for '192.168.11.162'
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 7
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] ASSERT: '3' .eq. '3
' failed. Recaching host '192.168.11.162', data query #606/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] NOTE: There are '33' Polling Items for this Host
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] DS[2205] SCRIPT: /usr/local/php/bin/php /var/www/html/cacti-0.8.7e/scripts/barracuda_total.php 192.168.11.162, output: allowed:3322940 blocked:24795659 quarantined:299126 tagged:10929 viruses:6029
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] DS[2206] SCRIPT: /usr/local/php/bin/php /var/www/html/cacti-0.8.7e/scripts/barracuda_perf.php 192.168.11.162, output: fw_storage_used:69 mail_storage_used:79
06/14/2010 03:23:56 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2207] SCRIPT: /usr/local/php/bin/php /var/www/html/cacti-0.8.7e/scripts/barracuda_temp.php 192.168.11.162, output: temp:22
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2208] SCRIPT: /usr/local/php/bin/php /var/www/html/cacti-0.8.7e/scripts/barracuda_total.php 192.168.11.162, output: allowed:3322940 blocked:24795659 quarantined:299126 tagged:10929 viruses:6029
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2209] SNMP: v2: 192.168.11.162, dsname: ssCPUIdle, oid: .1.3.6.1.4.1.2021.11.11.0, value: 92
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2210] SNMP: v2: 192.168.11.162, dsname: ssCPUSystem, oid: .1.3.6.1.4.1.2021.11.10.0, value: 1
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2211] SNMP: v2: 192.168.11.162, dsname: ssCPUUser, oid: .1.3.6.1.4.1.2021.11.9.0, value: 6
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2212] SNMP: v2: 192.168.11.162, dsname: dskAvail, oid: .1.3.6.1.4.1.2021.9.1.7.1, value: 45813788
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2213] SNMP: v2: 192.168.11.162, dsname: dskTotal, oid: .1.3.6.1.4.1.2021.9.1.6.1, value: 229611104
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2214] SNMP: v2: 192.168.11.162, dsname: dskUsed, oid: .1.3.6.1.4.1.2021.9.1.8.1, value: 172133728
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2215] SNMP: v2: 192.168.11.162, dsname: BounceMailQueue, oid: .1.3.6.1.4.1.2021.8.1.100.3, value: 0
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2216] SNMP: v2: 192.168.11.162, dsname: InMailQueue, oid: .1.3.6.1.4.1.2021.8.1.100.1, value: 0
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2217] SNMP: v2: 192.168.11.162, dsname: OutMailQueue, oid: .1.3.6.1.4.1.2021.8.1.100.2, value: 0
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2218] SNMP: v2: 192.168.11.162, dsname: memBuffer, oid: .1.3.6.1.4.1.2021.4.14.0, value: 87576
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2219] SNMP: v2: 192.168.11.162, dsname: memCached, oid: .1.3.6.1.4.1.2021.4.15.0, value: 898276
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2220] SNMP: v2: 192.168.11.162, dsname: memAvailReal, oid: .1.3.6.1.4.1.2021.4.6.0, value: 194200
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2221] SNMP: v2: 192.168.11.162, dsname: memTotalFree, oid: .1.3.6.1.4.1.2021.4.11.0, value: 1798072
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2222] SNMP: v2: 192.168.11.162, dsname: memTotalReal, oid: .1.3.6.1.4.1.2021.4.5.0, value: 2021380
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2223] SNMP: v2: 192.168.11.162, dsname: memTotalSwap, oid: .1.3.6.1.4.1.2021.4.3.0, value: 2048184
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 7
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2227] SCRIPT: perl /var/www/html/cacti-0.8.7e/scripts/query_unix_partitions.pl  get available /dev/sda1, output: 14343688
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 7
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2227] SCRIPT: perl /var/www/html/cacti-0.8.7e/scripts/query_unix_partitions.pl  get used /dev/sda1, output: 4033068
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 7
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2228] SCRIPT: perl /var/www/html/cacti-0.8.7e/scripts/query_unix_partitions.pl  get available /dev/sda2, output: 48207112
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 7
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2228] SCRIPT: perl /var/www/html/cacti-0.8.7e/scripts/query_unix_partitions.pl  get used /dev/sda2, output: 2607120
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 7
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2229] SCRIPT: perl /var/www/html/cacti-0.8.7e/scripts/query_unix_partitions.pl  get available /dev/sdb1, output: 73117512
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DEBUG: The NIFTY POPEN returned the following File Descriptor 7
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2229] SCRIPT: perl /var/www/html/cacti-0.8.7e/scripts/query_unix_partitions.pl  get used /dev/sdb1, output: 69919556
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2224] SNMP: v2: 192.168.11.162, dsname: traffic_in, oid: .1.3.6.1.2.1.2.2.1.10.2, value: 3991849502
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2224] SNMP: v2: 192.168.11.162, dsname: traffic_out, oid: .1.3.6.1.2.1.2.2.1.16.2, value: 632184454
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2225] SNMP: v2: 192.168.11.162, dsname: errors_in, oid: .1.3.6.1.2.1.2.2.1.14.2, value: 0
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2225] SNMP: v2: 192.168.11.162, dsname: discards_in, oid: .1.3.6.1.2.1.2.2.1.13.2, value: 0
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2225] SNMP: v2: 192.168.11.162, dsname: discards_out, oid: .1.3.6.1.2.1.2.2.1.19.2, value: 0
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2225] SNMP: v2: 192.168.11.162, dsname: errors_out, oid: .1.3.6.1.2.1.2.2.1.20.2, value: 0
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2226] SNMP: v2: 192.168.11.162, dsname: hdd_free, oid: .1.3.6.1.4.1.2021.9.1.7.1, value: 45813788
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DS[2226] SNMP: v2: 192.168.11.162, dsname: hdd_used, oid: .1.3.6.1.4.1.2021.9.1.8.1, value: 172133728
06/14/2010 03:23:57 PM - SPINE: Poller[0] Host[148] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
06/14/2010 03:23:57 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
06/14/2010 03:23:57 PM - SPINE: Poller[0] DEBUG: Thread Cleanup Complete
06/14/2010 03:23:57 PM - SPINE: Poller[0] DEBUG: PHP Script Server Pipes Closed
06/14/2010 03:23:57 PM - SPINE: Poller[0] DEBUG: Allocated Variable Memory Freed
06/14/2010 03:23:57 PM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
06/14/2010 03:23:57 PM - SPINE: Poller[0] Time: 1.3047 s, Threads: 15, Hosts: 2