random output from custom script being run

[julian924s]

Hi - hope someone can help with what should be a pretty simple script used to graph some data. I have a script that runs as the web server user and grabs 14 pieces of data from another server to graph. Running from the command line that the web server users runs as and the script works fine:

./session-count.sh
data1:13 data2:30 data3:160 data4:1 data5:1 data6:1047 data7:1 data8:1 data9:310 data10:23 data11:85 data12:126 data13:3005 data14:1372

Running the script from the command line consistently works.

So I've added the necessary Data Input Method, Data Template and Graph Template. However when I look at the cacti.log in debug I see entries like this:

07/04/2011 02:55:07 PM - SPINE: Poller[0] Host[12] TH[1] DS[210] SCRIPT: /usr/share/cacti/scripts/session-count.sh, output: 0
07/04/2011 03:00:06 PM - SPINE: Poller[0] Host[12] TH[1] DS[210] SCRIPT: /usr/share/cacti/scripts/session-count.sh, output: 0
07/04/2011 03:05:04 PM - CMDPHP: Poller[0] Host[12] DS[210] CMD: /usr/share/cacti/scripts/session-count.sh, output: data1:12 data2:30 data3:172 data4:1 data5:1 data6:1054
07/04/2011 03:10:03 PM - CMDPHP: Poller[0] Host[12] DS[210] CMD: /usr/share/cacti/scripts/session-count.sh, output: U
07/04/2011 03:15:04 PM - CMDPHP: Poller[0] Host[12] DS[210] CMD: /usr/share/cacti/scripts/session-count.sh, output: data1:15 data2:33 data3:162 data4:1 data5:1 data6:1054 data7:1

Has anyone any ideas why this is happening?

I'm running 0.8.7g on SLES 11. I have another graph that pulls just a single value from another server and that's working fine.

I've tried changing the poller from cmd to spine and enabled boost but still get totally random results.

Thanks.

[gandalf]

Please see 2nd link of my sig.
And please know, that for a multi-value putput, spine requires that this will be printed by a _single_ "print" statement
R.

[julian924s]

Thanks gandalf - have followed the details in your 2nd link and gone back to basics with the poller, so using cmd.php. The script / graph was working perfectly fine on our old Cacti server. Same version running just that it was on a Sun Solaris server wherea's the new one is Linux on Intel ... can't see that making any difference at all. As for the script this is it:

#!/bin/bash
#
/usr/bin/ssh -q user@server "/usr/bin/cat /export/home/db2inst1/user/sess.count"

And run from the command line:

wwwrun@cactiserver:/usr/share/cacti/scripts> ./session-count.sh
xxxxx:3 xxxxx:8 xxxxx:93 xxxxx:1 xxxxx:1 xxxxx:263 xxxxx:1 xxxxx:1 xxxxx:91 xxxxx:10 xxxxx:27 xxxxx:68 xxxxx:688 xxxxx:154

The value names are all unique and not "xxxxx" btw!

But I still just get the cacti.log file showing just 3 - 5 values returned each run when in debug mode - this is the output for a run just now:

07/07/2011 07:40:03 AM - CMDPHP: Poller[0] Host[12] DS[715] CMD: /usr/share/cacti/scripts/session-count.sh, output: xxxxx:2 xxxxx:9 xxxxx:103 xxxxx:1 xxxxx:1

From your debugging guide, if I run "php -q cmd.php 12 12" - 12 being the ID of the host in question the logfile shows me this:

07/07/2011 07:37:00 AM - CMDPHP: Poller[0] Host[12] DS[715] CMD: /usr/share/cacti/scripts/wbdbz1-session-count.sh, output: xxxxx:3 xxxxx:8 xxxxx:93 xxxxx:1 xxxxx:1 xxxxx:263 xxxxx:1 xxxxx:1 xxxxx:91 xxxxx:10 xxxxx:27 xxxxx:68 xxxxx:688 xxxxx:154

Which is what I want to see.

Any further help would be appreciated. I have several scripts like this that simply grab a list of figures. Two do work and they pull a single value and three values respectively so this one has me stumped as its not doing anything differently just it has more values being returned.

Thanks - J.

[gandalf]

And how is /export/home/db2inst1/user/sess.count filled? Is it possible, that there is a sync problem?
R.

[julian924s]

Hi - the sess.count file is populated from a script that runs every 5mins on the target server - a simple db2 script.

As a test today I did move the script so that it ran from the cacti server - so the cacti server connects to the db2 server via the db2 cli and issues the db2 commands itself.

The result was the same. One thing I did notice was that I happened to restart Apache just before a poll cycle and almost all values were returned so I've started to look at the php configuration file to see if the cmd.php running is hitting some kind of limit. Or even apache for that matter - but I'm just clutching at straws with these theories!!

The new cacti server is a far higher spec server so I like to think it isn't because of any kind of resource restrictions.

Actually just thinking about it could both cacti and the script that populates the sess.count file being running at the exact same time and the file getting messed up? I'll take a look tomorrow from work.

Thanks again for your help so far - J.

[gandalf]

Actually just thinking about it could both cacti and the script that populates the sess.count file being running at the exact same time and the file getting messed up?

That was my theory. We have some similar use cases. We run the script a minute earlier, then (4,9,14,19,24,29 ...)
R.

[julian924s]

Just a very quick update ... its still not working!

I've spent a bit of time playing around with the script and all I can say is however many items my output file has, whatever order they are in and whatever they are called - ONLY the first three values are ever plotted on the graph.

For the fourth, fifth, etc values I just get "-nan".

Have spent more time on this one graph then the hundred or so other ones, as well as actually building / installing / configuring the server .... to say I'm a little pi**ed at this now is a gross understatement.

J.

[gandalf]

Such an issue will occur in case you have modified the data template AFTER the rrd file has been created! New data sources will NOT make it into existing rrd files! Please see "rrdtool info <rrd file>" to verify
R.

[morten.damm]

Hi,
Please see my post

http://forums.cacti.net/viewtopic.php?f=21&t=43413

The problem seems similar to mine and it was solved enabling boost.

Morten

[julian924s]

Thanks - will have to take a look at that. I do get different results depending on whether I use cmd.php or spine which I don't understand either, eg.

spine:
07/15/2011 07:50:02 AM - SPINE: Poller[0] Host[12] TH[1] DS[995] SCRIPT: /bin/cat /home/db2inst1/test.out, output: 0
07/15/2011 07:55:03 AM - SPINE: Poller[0] Host[12] TH[1] DS[995] SCRIPT: /bin/cat /home/db2inst1/test.out, output: 0

cmd.php:
07/15/2011 08:25:03 AM - CMDPHP: Poller[0] Host[12] DS[997] CMD: /bin/cat /home/db2inst1/test.out, output: ireland:98 netherlands:1 enrolled:27 tdoffice:35
07/15/2011 08:30:02 AM - CMDPHP: Poller[0] Host[12] DS[997] CMD: /bin/cat /home/db2inst1/test.out, output: ireland:100 netherlands:1 enrolled:23 tdoffice:34

And as at present the graph displays ALL but the "enrolled" output - just get "-nan" for that, looking at the rrd file I can see this:

rrd_version = "0003"
step = 300
last_update = 1310715002
ds[enrolled].type = "GAUGE"
ds[enrolled].minimal_heartbeat = 600
ds[enrolled].min = 0.0000000000e+00
ds[enrolled].max = 5.0000000000e+03
ds[enrolled].last_ds = "U"
ds[enrolled].value = NaN
ds[enrolled].unknown_sec = 2

And a working entry:
ds[tdoffice].type = "GAUGE"
ds[tdoffice].minimal_heartbeat = 600
ds[tdoffice].min = 0.0000000000e+00
ds[tdoffice].max = 5.0000000000e+03
ds[tdoffice].last_ds = "34"
ds[tdoffice].value = 6.8000000000e+01
ds[tdoffice].unknown_sec = 0

Also gandalf did mention about making modifications to data templates after the rrd has been created, so I have been careful to remove the graph via Graph Management and add it as a new graph for the device in question.

Thanks.

[julian924s]

OK, so using cmd.php my graph with only three pieces of data output is fine. I've removed the graph and edited the necessary templates so a fourth piece of data was output, added the graph again and let the poller run a couple of times. And now I get "-nan" again for the 4th item only. And looking in the cacti.log I can see this:

07/15/2011 09:25:02 AM - CMDPHP: Poller[0] Host[12] DS[999] CMD: /bin/cat /home/db2inst1/test.out, output: ireland:110 netherlands:1 tdoffice:54 remoteservices:28
07/15/2011 09:30:03 AM - CMDPHP: Poller[0] Host[12] DS[999] CMD: /bin/cat /home/db2inst1/test.out, output: ireland:111 netherlands:1 tdoffice:52 remoteservices:28

So for whatever reason any more than three items of data from my script and its not working, I've looked at spine again - removed / reinstalled / checked etc and all I get is this in the logs:

07/15/2011 09:35:02 AM - SPINE: Poller[0] Host[12] TH[1] DS[1000] SCRIPT: /bin/cat /home/db2inst1/test.out, output: 0

So for me spine just doesn't work.

[julian924s]

And running spine from the command line I get this:

/usr/local/spine/bin/spine -C /usr/local/spine/etc/spine.conf --verbosity=5 12 12
SPINE: Using spine config file [/usr/local/spine/etc/spine.conf]
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The path_php_server variable is /usr/share/cacti/script_server.php
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The path_cactilog variable is /var/log/cacti/cacti.log
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The log_destination variable is 1 (FILE)
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The path_php variable is /usr/bin/php
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The availability_method variable is 2
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The ping_recovery_count variable is 3
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The ping_failure_count variable is 2
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The ping_method variable is 2
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The ping_retries variable is 1
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The ping_timeout variable is 400
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The snmp_retries variable is 3
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The log_perror variable is 1
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The log_pwarn variable is 0
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The boost_redirect variable is 0
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The log_pstats variable is 0
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The threads variable is 1
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The polling interval is 300 seconds
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The number of concurrent processes is 8
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The script timeout is 50
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The number of php script servers to run is 1
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: StartHost='12', EndHost='12', TotalPHPScripts='0'
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The PHP Script Server is Not Required
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The Maximum SNMP OID Get Size is 1
07/15/2011 09:58:12 AM - SPINE: Poller[0] Version 0.8.7g starting
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: MySQL is Thread Safe!
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: Spine is running asroot.
07/15/2011 09:58:12 AM - SPINE: Poller[0] SPINE: Initializing Net-SNMP API
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: Issues with SNMP Header Version information, assuming old version of Net-SNMP.
07/15/2011 09:58:12 AM - SPINE: Poller[0] SPINE: Initializing PHP Script Server(s)
07/15/2011 09:58:12 AM - SPINE: Poller[0] NOTE: Spine did not detect multithreaded device polling.
07/15/2011 09:58:12 AM - SPINE: Poller[0] NOTE: Spine is behaving in a 0.8.7g manner
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: Initial Value of Active Threads is 0
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
07/15/2011 09:58:12 AM - SPINE: Poller[0] Host[0] TH[1] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: Valid Thread to be Created
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: In Poller, About to Start Polling of Host
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 1
07/15/2011 09:58:12 AM - SPINE: Poller[0] Host[12] No Host Availability Method Selected
07/15/2011 09:58:12 AM - SPINE: Poller[0] Host[12] TH[1] Host has no information for recache.
07/15/2011 09:58:12 AM - SPINE: Poller[0] Host[12] TH[1] NOTE: There are '1' Polling Items for this Host
07/15/2011 09:58:12 AM - SPINE: Poller[0] Host[12] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
07/15/2011 09:58:12 AM - SPINE: Poller[0] Host[12] TH[1] DS[1000] SCRIPT: /bin/cat /home/db2inst1/test.out, output: 0
07/15/2011 09:58:12 AM - SPINE: Poller[0] Host[12] TH[1] DEBUG: HOST COMPLETE: About to Exit Host Polling Thread Function
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: The Value of Active Threads is 0
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: Thread Cleanup Complete
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: PHP Script Server Pipes Closed
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: Allocated Variable Memory Freed
07/15/2011 09:58:12 AM - SPINE: Poller[0] DEBUG: MYSQL Free & Close Completed
07/15/2011 09:58:12 AM - SPINE: Poller[0] Time: 0.0645 s, Threads: 1, Hosts: 2


And again the log file just shows:

07/15/2011 09:58:12 AM - SPINE: Poller[0] Host[12] TH[1] DS[1000] SCRIPT: /bin/cat /home/db2inst1/test.out, output: 0


But the actual file contains data:

/bin/cat /home/db2inst1/test.out
ireland:113 netherlands:1 tdoffice:60 remoteservices:19

Have checked file / folder permissions multiple times as well, just not got a clue now.

[julian924s]

Hi Morten - had a read through your post and exactly the same for me, apart from I cannot get more than 3 items of data to graph - adding a fourth just shows "-nan" or "U" in the rrd as already mentioned. Spine is even worse - output is just "0". And enabling boost with cmd.php still limits to 3 values.

My other couple of hundred other graphs are all fine, just none of my custom scripted ones will work.

All in all, thoroughly fed up with this now.

[gandalf]

OK, so using cmd.php my graph with only three pieces of data output is fine. I've removed the graph and edited the necessary templates so a fourth piece of data was output, added the graph again and let the poller run a couple of times. And now I get "-nan" again for the 4th item only. And looking in the cacti.log I can see this:

07/15/2011 09:25:02 AM - CMDPHP: Poller[0] Host[12] DS[999] CMD: /bin/cat /home/db2inst1/test.out, output: ireland:110 netherlands:1 tdoffice:54 remoteservices:28
07/15/2011 09:30:03 AM - CMDPHP: Poller[0] Host[12] DS[999] CMD: /bin/cat /home/db2inst1/test.out, output: ireland:111 netherlands:1 tdoffice:52 remoteservices:28

So for whatever reason any more than three items of data from my script and its not working, I've looked at spine again - removed / reinstalled / checked etc and all I get is this in the logs:

07/15/2011 09:35:02 AM - SPINE: Poller[0] Host[12] TH[1] DS[1000] SCRIPT: /bin/cat /home/db2inst1/test.out, output: 0

So for me spine just doesn't work.

Deleteing the graph won't help. You'll need to delete the data source and the graph.
And you may want to try latest spine from SVN/0.8.7; we had some changes lately.
R.

[julian924s]

Thanks - will try the newer spine code. But today I deleted the items from the following locations and it still doesn't work - in fact its worse, only get 2 out of four items displayed now. Although the cacti logs show ALL 4 being returned.

Deleted from:
Graph Management
Data Sources
Data Input Methods
Data Template
Graph Template

And created new ones with a completely different name.

J.