Difference in PHP output of CLI script run vs SPINE run

[coolerl]

Hi guys,
I have this error that I cannot seem to catch from where it comes.

When I run my PHP script from CLI this is what I get:
[coolerl@vsm ~]$ php /usr/share/cacti/scripts/get_appear_input_status.php 172.27.16.71
SrvS0:96 IFAS0:678.646 IFBS0:678.635 TSRateS0:649.872 EffRateS0:528.692 BPRateS0:700.393 CCErrS0:29610 TSErrS0:271 SEQErrAS0:37171 SEQErrBS0:590 NOKSEQErrS0:7 SrvS1:94 IFAS1:626.434 IFBS1:626.456 TSRateS1:600.012 EffRateS1:511.386 BPRateS1:646.505 CCErrS1:18562 TSErrS1:0 SEQErrAS1:42801 SEQErrBS1:510 NOKSEQErrS1:8

However, when it runs from Spine, things look incomplete and different with each running iteration:

Iteration1:
Total[0.1134] Device[434] DEBUG: Entering ICMP Ping
Total[0.1135] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1136] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1137] Device[434] DEBUG: Attempting to ping 172.27.16.71, seq 0 (Retry 0 of 1)
Total[0.1203] Device[434] DEBUG: ICMP Device Alive, Try Count:1, Time:6.6159 ms
Total[0.1203] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1204] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1204] Device[434] DEBUG: Entering SNMP Ping
Total[0.1274] Device[434] PING Result: ICMP: Device is Alive
Total[0.1274] Device[434] SNMP Result: Device responded to SNMP
Total[0.1274] Device[434] Checking for System Information Update
Total[0.1274] Device[434] Updating Full System Information Table
Total[0.1684] Device[434] HT[1] Device has no information for recache.
Total[0.1690] Device[434] HT[1] NOTE: There are '1' Polling Items for this Device
Total[0.1692] DEBUG: Device[434] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
Total[0.3062] Device[434] HT[1] DS[6151] TT[137.17] SCRIPT: php /usr/share/cacti/scripts/get_appear_input_status.php '172.27.16.71', output: SrvS0:96 IFAS0:678.646 IFBS0:678.657 TSRateS0:649.872 EffRateS0:535.644 BPRateS0:700.358 CCErrS0:30830 TSErrS0:271 SEQErrAS0:37240 SEQErrBS0:590 NOKSEQErrS0:7
Total[0.3063] DEBUG: Setting up writes to local database
Total[0.3063] Device[434] HT[1] Total Time: 0.19 Seconds

Iteration2:
Total[0.1113] Device[434] DEBUG: Entering ICMP Ping
Total[0.1114] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1114] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1115] Device[434] DEBUG: Attempting to ping 172.27.16.71, seq 0 (Retry 0 of 1)
Total[0.1181] Device[434] DEBUG: ICMP Device Alive, Try Count:1, Time:6.6001 ms
Total[0.1181] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1182] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1182] Device[434] DEBUG: Entering SNMP Ping
Total[0.1246] Device[434] PING Result: ICMP: Device is Alive
Total[0.1246] Device[434] SNMP Result: Device responded to SNMP
Total[0.1246] Device[434] Checking for System Information Update
Total[0.1246] Device[434] Updating Full System Information Table
Total[0.5899] Device[434] HT[1] Device has no information for recache.
Total[0.5903] Device[434] HT[1] NOTE: There are '1' Polling Items for this Device
Total[0.5905] DEBUG: Device[434] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
Total[0.6183] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.7193] Device[434] HT[1] DS[6151] TT[128.96] SCRIPT: php /usr/share/cacti/scripts/get_appear_input_status.php '172.27.16.71', output: SrvS0:96 IFAS0:678.646 IFBS0:678.624
Total[0.7194] DEBUG: Setting up writes to local database
Total[0.7195] Device[434] HT[1] Total Time: 0.61 Seconds

Iteration3:
Total[0.1140] Device[434] DEBUG: Entering ICMP Ping
Total[0.1141] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1141] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1141] Device[434] DEBUG: Attempting to ping 172.27.16.71, seq 0 (Retry 0 of 1)
Total[0.1211] Device[434] DEBUG: ICMP Device Alive, Try Count:1, Time:6.9442 ms
Total[0.1211] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1212] WARNING: Device[434] polling sleeping while waiting for 1 Threads to End
Total[0.1212] Device[434] DEBUG: Entering SNMP Ping
Total[0.1282] Device[434] PING Result: ICMP: Device is Alive
Total[0.1282] Device[434] SNMP Result: Device responded to SNMP
Total[0.1282] Device[434] Checking for System Information Update
Total[0.1282] Device[434] Updating Full System Information Table
Total[0.1701] Device[434] HT[1] Device has no information for recache.
Total[0.1706] Device[434] HT[1] NOTE: There are '1' Polling Items for this Device
Total[0.1707] DEBUG: Device[434] DEBUG: The NIFTY POPEN returned the following File Descriptor 6
Total[0.3172] Device[434] HT[1] DS[6151] TT[146.58] SCRIPT: php /usr/share/cacti/scripts/get_appear_input_status.php '172.27.16.71', output: SrvS0:96 IFAS0:678.657 IFBS0:678.657 TSRateS0:650.020 EffRateS0:533.147 BPRateS0:700.381 CCErrS0:30830 TSErrS0:271 SEQErrAS0:37300
Total[0.3173] DEBUG: Setting up writes to local database
Total[0.3174] Device[434] HT[1] Total Time: 0.2 Seconds

Any ideeas on why this is happening and what might be wrong?

Thanks!

[macan]

The similar issue was here recently
viewtopic.php?t=62336

[coolerl]

The similar issue was here recently
viewtopic.php?t=62336

Hi Macan,
Unfortunately path and variables are not the issue here, as the script returns the values both under the CLI and under SPINE.

The problem is that the number of values is incomplete when SPINE runs the script.

I'll clearly exemplify below:

When I run the script from the CLI
cacti]# /usr/bin/php /usr/share/cacti/scripts/get_appear_input_status.php 172.27.16.71 | grep -n -o ":" | wc -l
22

However, when the exact same script is ran by SPINE, the result number is never 22, and it always varies between 2 and 9.

cacti]# /usr/bin/spine -R -V 5 -f 434 -l 434 -S | grep "output:" | grep -n -o ":" | wc -l
9
cacti]# /usr/bin/spine -R -V 5 -f 434 -l 434 -S | grep "output:" | grep -n -o ":" | wc -l
4
cacti]# /usr/bin/spine -R -V 5 -f 434 -l 434 -S | grep "output:" | grep -n -o ":" | wc -l
5
/usr/bin/spine -R -V 5 -f 434 -l 434 -S | grep "output:" | grep -n -o ":" | wc -l
7
/usr/bin/spine -R -V 5 -f 434 -l 434 -S | grep "output:" | grep -n -o ":" | wc -l
5

Since this is always happening, on the graph I've created, I sometimes have values, sometimes I don't, depending if the value is delivered by spine or not.

[coolerl]

Anyone got any ideeas that could shed some light on the issue?

As consequence of the fact presented above, the virst value is always presented to Cacti because the first value is always present in the script output.
However, the 2nd value lies somewhere at the 12th value reported by the script, thus is only arives seldomly to cacti for processing.

As a result, the graph looks like below:

Capture.PNG (12.84 KiB) Viewed 621 times

[coolerl]

I would be very thankfull fore some ideeas here
I'm quite stuck

[Osiris]

Your script must output all data at once. If it's doing multiple echos/prints, it won't work. This is different than cmd.php

[coolerl]

Osiris you are a life saver!
Thanks a great lot for your feedback!

Indeed that was the problem: my script was sending each value to the output, via a sepparate echo instruction.
I've corrected the script to have them all sent via $output and now everything is working correctly and all the 24 values are collected by spine!

/usr/bin/spine -R -V 5 -f 434 -l 434 -S | grep "output:" | grep -n -o ":" | wc -l
24

Many thanks again!
Great tip!

Your script must output all data at once. If it's doing multiple echos/prints, it won't work. This is different than cmd.php