troubleshooting spine

[jftuga]

My graphs are not being updated when using spine. Under cmd.php, graph updates work fine. I have a new install of FreeBSD 9.0 and Cacti 0.88a. What are the best steps to debug this?


Thanks,
-John

[stigia]

did you rebuild the poller cache on settings? after you change the poller type?

[jftuga]

No, I did not. How do you do this?

Once I get to Utilities -> System Utilities -> Rebuild Poller Cache, I see 5 entries for localhost. What do I do next?
EDIT: Ah, now I see that this is a CLI script. I will run this.

Thanks,
-John

[jftuga]

Rebuilding the poller cache did not work.

I artifically increased the load average, increased the process count & number of logins, but these are not reflected on new Cacti graphs even after waiting 15 minutes.

I also deleted the memory usage data sources & graphs, since those are Linux specific and I am running FreeBSD 9.0.

-John

Code: Select all

(svrcacti00)(/cacti/log) /usr/local/bin/spine -V 5
SPINE: Using spine config file [/usr/local/etc/spine.conf]
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The path_php_server variable is /usr/local/share/cacti/script_server.php
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The path_cactilog variable is /usr/local/share/cacti/log/cacti.log
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The log_destination variable is 1 (FILE)
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The path_php variable is /usr/local/bin/php
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The availability_method variable is 2
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The ping_recovery_count variable is 3
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The ping_failure_count variable is 2
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The ping_method variable is 2
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The ping_retries variable is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The ping_timeout variable is 400
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The snmp_retries variable is 3
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The log_perror variable is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The log_pwarn variable is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The boost_redirect variable is 0
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The log_pstats variable is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The threads variable is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The polling interval is 300 seconds
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The number of concurrent processes is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The script timeout is 25
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The number of php script servers to run is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: StartHost='-1', EndHost='-1', TotalPHPScripts='0'
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The PHP Script Server is Not Required
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The Maximum SNMP OID Get Size is 10
08/03/2012 05:03:01 PM - SPINE: Poller[0] Version 0.8.8 starting
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: MySQL is Thread Safe!
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: Spine is running asroot.
08/03/2012 05:03:01 PM - SPINE: Poller[0] SPINE: Initializing Net-SNMP API

08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: Issues with SNMP Header Version information, assuming old version of Net-SNMP.
(I am using net-snmp-5.7.1_7 and php5-snmp-5.4.5)

08/03/2012 05:03:01 PM - SPINE: Poller[0] SPINE: Initializing PHP Script Server(s)
08/03/2012 05:03:01 PM - SPINE: Poller[0] NOTE: Spine will support multithread device polling.
08/03/2012 05:03:01 PM - SPINE: Poller[0] NOTE: Spine is behaving in a 0.8.7g+ manner
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: Initial Value of Active Threads is 0
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[0] TH[1] Total Time: 0.00093 Seconds
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[0] TH[1] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] DEBUG: Entering UDP Ping
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] DEBUG: UDP Host Alive, Try Count:1, Time:0.0291 ms
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] PING: Result UDP: Host is Alive
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] TH[1] Host has no information for recache.
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] TH[1] NOTE: There are '3' Polling Items for this Host
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] TH[1] DS[5] SCRIPT: perl /usr/local/share/cacti/scripts/loadavg_multi.pl, output: 1min:2.56 5min:3.01 10min:2.77
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] TH[1] DS[6] SCRIPT: perl /usr/local/share/cacti/scripts/unix_users.pl , output: 5
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] TH[1] DS[7] SCRIPT: perl /usr/local/share/cacti/scripts/unix_processes.pl, output: 116
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] TH[1] Total Time: 0.021 Seconds
08/03/2012 05:03:01 PM - SPINE: Poller[0] Host[1] TH[1] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: Thread Cleanup Complete
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: PHP Script Server Pipes Closed
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: Allocated Variable Memory Freed
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
08/03/2012 05:03:01 PM - SPINE: Poller[0] DEBUG: Net-SNMP Close Completed
08/03/2012 05:03:01 PM - SPINE: Poller[0] Time: 0.0501 s, Threads: 1, Hosts: 2

[jftuga]

I still have not resolved this. Any ideas?
I am seeing this in the cacti.log. When I run these from cmd-line, they work fine albeit without a new line character at the end.

08/06/2012 03:55:00 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] TH[1] Host has no information for recache.
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] TH[1] NOTE: There are '3' Polling Items for this Host
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] DEBUG: The POPEN returned the following File Descriptor 7
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] ERROR: Empty result [127.0.0.1]: 'perl /usr/local/share/cacti/scripts/loadavg_multi.pl'
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] TH[1] DS[16] SCRIPT: perl /usr/local/share/cacti/scripts/loadavg_multi.pl, output: U
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] DEBUG: The POPEN returned the following File Descriptor 7
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] ERROR: Empty result [127.0.0.1]: 'perl /usr/local/share/cacti/scripts/unix_processes.pl'
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] TH[1] DS[12] SCRIPT: perl /usr/local/share/cacti/scripts/unix_processes.pl, output: U
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] DEBUG: The POPEN returned the following File Descriptor 7
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] ERROR: Empty result [127.0.0.1]: 'perl /usr/local/share/cacti/scripts/unix_users.pl '
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] TH[1] DS[14] SCRIPT: perl /usr/local/share/cacti/scripts/unix_users.pl , output: U
08/06/2012 03:55:00 PM - SPINE: Poller[0] Host[1] TH[1] Total Time: 0.014 Seconds

If I compile spine with --enable-popen, then I get this below. But this is only when running from the command line. Running from the 5 minute cron job still reports the ERROR.

08/06/2012 03:55:14 PM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] DEBUG: Entering UDP Ping
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] DEBUG: UDP Host Alive, Try Count:1, Time:0.0310 ms
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] PING: Result UDP: Host is Alive
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] TH[1] Host has no information for recache.
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] TH[1] NOTE: There are '3' Polling Items for this Host
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] DEBUG: The POPEN returned the following File Descriptor 6
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] TH[1] DS[16] SCRIPT: perl /usr/local/share/cacti/scripts/loadavg_multi.pl, output: 1min:4.02 5min:3.82 10min:3.33
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] DEBUG: The POPEN returned the following File Descriptor 6
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] TH[1] DS[12] SCRIPT: perl /usr/local/share/cacti/scripts/unix_processes.pl, output: 86
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] DEBUG: The POPEN returned the following File Descriptor 6
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] TH[1] DS[14] SCRIPT: perl /usr/local/share/cacti/scripts/unix_users.pl , output: 9
08/06/2012 03:55:14 PM - SPINE: Poller[0] Host[1] TH[1] Total Time: 0.024 Seconds

Thanks,
-John

[jftuga]

Ok, I am still tracking down this problem. If I run the poller.php cron job as root, there are no errors in the cacti.log file and graphs are being created. When I was having the problem, the 'cacti' user was running the cron job.

I believe the problem is with the popen function:

From the man page:

Code: Select all

FILE * popen(const char *command, const char *type);

This command is passed to /bin/sh using the -c flag; interpretation, if any, is performed by the shell.

I think my issue is that I have this entry in /etc/passwd which is causing popen() to fail:

cacti:*:107:107:Cacti Sandbox:/nonexistent:/sbin/nologin

This entry was automatically added in by the FreeBSD ports install routine. I am going to change this to use a normal directory and shell and see if this fixes the problem. The odd thing is, I would get a legitamate File Descriptor return value for the popen() function, which was displayed in the cacti.log file.

-John

[jftuga]

I changed the home dir to /tmp and the shell to /bin/sh. And the errors showed up again.

So how bad is it to run poller.php as root?

Any ideas?

Thanks,
-John

[gandalf]

I still have not resolved this. Any ideas?
I am seeing this in the cacti.log. When I run these from cmd-line, they work fine albeit without a new line character at the end.

If I compile spine with --enable-popen, then I get this below. But this is only when running from the command line. Running from the 5 minute cron job still reports the ERROR.

This looks like an issue with the net-snmp libraries; perhaps an issue with the path to those. In case the paths differ for your userid and the root user, sth like the encountered behaviour is to be expected
R.