Cacti log file reporting "Poller Output Table not Empty

[clangro]

I've been working on cleaning up my Cacti server and I've been stumped on this issue. Every 5 minute polling interval in the logs shows me this:

07/07/2010 12:50:01 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 451, Data Sources: asa5min_cpu(DS[5862]), ike_tunnels(DS[5863]), ipsec_tunnels(DS[5864]), dropped_in(DS[5865]), dropped_out(DS[5866]), traffic_in(DS[5867]), traffic_out(DS[5868]), asa_memfree(DS[5869]), asa_memused(DS[5870]), crasNumSessions(DS[5871]), asa_conn(DS[5872]), RX(DS[5875]), RX(DS[5875]), TX(DS[5875]), TX(DS[5875]), RX(DS[5876]), RX(DS[5876]), TX(DS[5876]), TX(DS[5876]), RX(DS[5877]), RX(DS[5877]), Additional Issues Remain. Only showing first 20
07/07/2010 12:45:02 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 336, Data Sources: RX(DS[6286]), RX(DS[6287]), TX(DS[6287]), RX(DS[6288]), TX(DS[6288]), RX(DS[6289]), TX(DS[6289]), RX(DS[6290]), TX(DS[6290]), RX(DS[6291]), TX(DS[6291]), RX(DS[6292]), TX(DS[6292]), RX(DS[6293]), TX(DS[6293]), RX(DS[6294]), TX(DS[6294]), RX(DS[6295]), TX(DS[6295]), RX(DS[6296]), TX(DS[6296]), Additional Issues Remain. Only showing first 20
07/07/2010 12:40:01 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 397, Data Sources: RX(DS[5875]), TX(DS[5875]), RX(DS[5876]), TX(DS[5876]), RX(DS[5877]), TX(DS[5877]), RX(DS[5878]), TX(DS[5878]), RX(DS[6249]), TX(DS[6249]), RX(DS[6250]), TX(DS[6250]), RX(DS[6251]), TX(DS[6251]), RX(DS[6252]), TX(DS[6252]), RX(DS[6253]), TX(DS[6253]), RX(DS[6254]), TX(DS[6254]), RX(DS[6255]), Additional Issues Remain. Only showing first 20
07/07/2010 12:35:01 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 412, Data Sources: RX(DS[5875]), TX(DS[5875]), RX(DS[5876]), TX(DS[5876]), RX(DS[5877]), TX(DS[5877]), RX(DS[5878]), TX(DS[5878]), RX(DS[6184]), TX(DS[6184]), RX(DS[6202]), TX(DS[6202]), RX(DS[6203]), TX(DS[6203]), RX(DS[6204]), TX(DS[6204]), RX(DS[6205]), TX(DS[6205]), RX(DS[6206]), TX(DS[6206]), RX(DS[6207]), Additional Issues Remain. Only showing first 20
07/07/2010 12:30:02 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 796, Data Sources: asa5min_cpu(DS[5862]), ike_tunnels(DS[5863]), ipsec_tunnels(DS[5864]), dropped_in(DS[5865]), dropped_out(DS[5866]), traffic_in(DS[5867]), traffic_out(DS[5868]), asa_memfree(DS[5869]), asa_memused(DS[5870]), crasNumSessions(DS[5871]), asa_conn(DS[5872]), RX(DS[5875]), TX(DS[5875]), RX(DS[5876]), TX(DS[5876]), RX(DS[5877]), TX(DS[5877]), RX(DS[5878]), TX(DS[5878]), traffic_in(DS[5879]), traffic_out(DS[5879]), Additional Issues Remain. Only showing first 20
07/07/2010 12:25:01 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 751, Data Sources: asa5min_cpu(DS[5862]), ike_tunnels(DS[5863]), ipsec_tunnels(DS[5864]), dropped_in(DS[5865]), dropped_out(DS[5866]), traffic_in(DS[5867]), traffic_out(DS[5868]), asa_memfree(DS[5869]), asa_memused(DS[5870]), crasNumSessions(DS[5871]), asa_conn(DS[5872]), RX(DS[5875]), TX(DS[5875]), RX(DS[5876]), TX(DS[5876]), RX(DS[5877]), TX(DS[5877]), RX(DS[5878]), TX(DS[5878]), traffic_in(DS[5879]), traffic_out(DS[5879]), Additional Issues Remain. Only showing first 20
07/07/2010 12:20:01 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 885, Data Sources: asa5min_cpu(DS[5862]), ike_tunnels(DS[5863]), ipsec_tunnels(DS[5864]), dropped_in(DS[5865]), dropped_out(DS[5866]), traffic_in(DS[5867]), traffic_out(DS[5868]), asa_memfree(DS[5869]), asa_memused(DS[5870]), crasNumSessions(DS[5871]), asa_conn(DS[5872]), RX(DS[5875]), TX(DS[5875]), RX(DS[5876]), TX(DS[5876]), RX(DS[5877]), TX(DS[5877]), RX(DS[5878]), TX(DS[5878]), traffic_in(DS[5879]), traffic_out(DS[5879]), Additional Issues Remain. Only showing first 20
07/07/2010 12:15:01 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 947, Data Sources: asa5min_cpu(DS[5862]), ike_tunnels(DS[5863]), ipsec_tunnels(DS[5864]), dropped_in(DS[5865]), dropped_out(DS[5866]), traffic_in(DS[5867]), traffic_out(DS[5868]), asa_memfree(DS[5869]), asa_memused(DS[5870]), crasNumSessions(DS[5871]), asa_conn(DS[5872]), RX(DS[5875]), TX(DS[5875]), RX(DS[5876]), TX(DS[5876]), RX(DS[5877]), TX(DS[5877]), RX(DS[5878]), TX(DS[5878]), traffic_in(DS[5879]), traffic_out(DS[5879]), Additional Issues Remain. Only showing first 20

I've pulled up every data source and here is what I've determined so far:

- Cacti monitors 50% Cisco ASAs on one interface and 50% Juniper FWs on another interface. The Juniper FWs are all fine and dandy reporting, but about 2/3rd of the Cisco ASAs have gaps in graph data. They are all using the same templates.

- Out of all of the data sources that are linked in the log file, all of them are Cisco ASAs. Granted, these are only the first 20 of each batch, but working from multiple batches as well as the info reported above, I feel confident saying that the ASAs are the only devices having a problem.

- When pulling up some of the data sources, they seem to not exist as I get this error: "Error: Data Source "5876" does not exist."

- Resource utilization on this server is pretty low. load average: 0.39, 0.45, 0.79

- This is a RHEL 5 box running Cacti 0.8.7e using the default poller.

I'd like help trying to clear this error, as I think it is what is causing the gaps in graph data.

[mcutting]

Take a look in the CLI directory. There is a script there that can be run from the command line that will empty the poller_output table.

[clangro]

Take a look in the CLI directory. There is a script there that can be run from the command line that will empty the poller_output table.

Thanks. It actually looks like it took care of itself as I deleted a bunch of data sources I didn't need anymore.

[TheWitness]

So, tell us what happened? Did you delete a bunch of devices and leave the graphs around, or did you delete a bunch or graphs and leave the data sources around?

TheWitness

[philipz]

I'm having a similar issue:
07/27/2010 03:11:58 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 3487, Data Sources: bytes(DS[674]), bytes(DS[679]), bytes(DS[684]), bytes(DS[689]), bytes(DS[694]), drops(DS[699]), bytes(DS[705]), bytes(DS[710]), bytes(DS[715]), bytes(DS[720]), drops(DS[725]), bytes(DS[730]), bytes(DS[735]), bytes(DS[740]), bytes(DS[745]), drops(DS[750]), bytes(DS[755]), bytes(DS[760]), bytes(DS[765]), bytes(DS[770]), bytes(DS[775]), Additional Issues Remain. Only showing first 20
...

I increased PHP's memory and did empty the poller_output table via the script.
I also played around with snmp settings, but then figured out that it queries snmp via a perl script (cbwfs.pl) so that will not help anyway.

This is part of the log:
07/27/2010 03:19:20 PM - SYSTEM STATS: Time:26.0335 Method:spine Processes:1 Threads:20 Hosts:552 HostsPerProcess:552 DataSources:3579 RRDsProcessed:2630
...
07/27/2010 03:17:58 PM - SYSTEM STATS: Time:0.1168 Method:spine Processes:1 Threads:20 Hosts:552 HostsPerProcess:552 DataSources:3579 RRDsProcessed:0
07/27/2010 03:17:58 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
07/27/2010 03:17:20 PM - SYSTEM STATS: Time:26.1494 Method:spine Processes:1 Threads:20 Hosts:552 HostsPerProcess:552 DataSources:3579 RRDsProcessed:2627

spine takes 26 seconds to process; not sure what the poller stats are

[TheWitness]

If polling at 1 minute, please set your Crontab and cron entry in Cacti to 1 minute also. This is a bug with 0.8.7g.

TheWitness

[philipz]

Ouch I didn't know that...
Will it do any harm if I don't change it? I don't want to overload my systems with more frequent polling...
Poller = every minute, cron = every 5 minutes

Is this a cosmetic bug anyway? I don't see any gaps in the graphs related to those datasources/hosts, that's why I'm asking.

Thanks!

[TheWitness]

It's more than cosmetic at this point. I have to figure it out, but have not had time as yet. It has to do with the second poll in a 5 minute loop loosing track of both the begin and end host id's.

If you can figure out what's going on in the code, I will commit the patch. Right now I'm too busy.

TheWitness

[philipz]

If you can figure out what's going on in the code, I will commit the patch. Right now I'm too busy.
TheWitness

Well - I'm not really a coder so pretty hard for me to dig into it...
I changed poller interval to 5 minutes so that cron and poller are in sync, see if that will help.

Btw for me spine0.8.7g did not work either, I had to revert to the f version (gives me the POLLER: Poller[0] Maximum runtime exceeded error as well, see this thread: http://forums.cacti.net/viewtopic.php?t ... c&start=15

[philipz]

If polling at 1 minute, please set your Crontab and cron entry in Cacti to 1 minute also. This is a bug with 0.8.7g.

TheWitness

Is that bug already patched somewhere?
The bug that you describe, is that "Poller Output Table not Empty" due to "Maximum runtime of 298 seconds exceeded?"
If I run spine manually it finishes in 36 seconds, so it should definitely be finished within 300 seconds...

Again, much appreciated!

[TheWitness]

I have it marked 'resolved' although there is still a specific issue for the user.

http://bugs.cacti.net/view.php?id=1815

TheWitness

[philipz]

Unfortunately it didn't fix the issue for me:

08/02/2010 11:51:55 PM - SYSTEM STATS: Time:0.3895 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3370 RRDsProcessed:4
08/02/2010 11:51:55 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/02/2010 11:51:42 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 32, Data Sources: bytes(DS[7898]), bytes(DS[7899]), bytes(DS[7900]), bytes(DS[7901]), bytes(DS[7902]), bytes(DS[7903]), bytes(DS[7904]), bytes(DS[7905]), bytes(DS[7906]), bytes(DS[7907]), bytes(DS[7908]), drops(DS[7909]), drops(DS[7910]), drops(DS[7911]), drops(DS[7912]), drops(DS[7913]), bytes(DS[9055]), bytes(DS[9056]), bytes(DS[9057]), bytes(DS[9058]), bytes(DS[9059]), Additional Issues Remain. Only showing first 20
08/02/2010 11:50:23 PM - SYSTEM STATS: Time:22.7076 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3083 RRDsProcessed:3637

Any debug that I can post to help find the root cause?

cheers

[TheWitness]

Post your debug to the ticket.

TheWitness

[philipz]

Post your debug to the ticket.

TheWitness

Debug.txt uploaded to the bug tracker, but I could not add a note (The action cannot be performed because issue "1815" is read-only.)


while performing the debug I saw lots of these messages:
...
Cannot find module (BIDON): At line 0 in (none)
Cannot find module (BIDON): At line 0 in (none)
Cannot find module (BIDON): At line 0 in (none)
Cannot find module (BIDON): At line 0 in (none)
...

Not sure if it is related though.

Thanks

[TheWitness]

Post your debug to the ticket.

TheWitness

Debug.txt uploaded to the bug tracker, but I could not add a note (The action cannot be performed because issue "1815" is read-only.)


while performing the debug I saw lots of these messages:
...
Cannot find module (BIDON): At line 0 in (none)
Cannot find module (BIDON): At line 0 in (none)
Cannot find module (BIDON): At line 0 in (none)
Cannot find module (BIDON): At line 0 in (none)
...

Not sure if it is related though.

Thanks

The clock on your machine must be hosted, or the usleep function is not working correctly, or some other plugin related issue. Not sure which it is. Here I will demonstrate.

Code: Select all

08/03/2010 10:34:47 AM - POLLER: Poller[0] NOTE: Poller Int: '60', Cron Int: '300', Time Since Last: '287', Max Runtime '298', Poller Runs: '5'
08/03/2010 10:34:47 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine2/bin/spine, ARGS:  0 324]
08/03/2010 10:34:47 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine2/bin/spine, ARGS:  325 685]
08/03/2010 10:34:47 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine2/bin/spine, ARGS:  689 905]
Waiting on 1 of 3 pollers.
08/03/2010 10:35:25 AM - SYSTEM STATS: Time:38.3156 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3467 RRDsProcessed:2554
Loop  Time is: 38.32
Sleep Time is: 21.64
Total Time is: 38.36
08/03/2010 10:36:39 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty.  Issues Found: 3348, Data Sources: bytes(DS[675]), bytes(DS[680]), bytes(DS[685]), bytes(DS[690]), bytes(DS[695]), drops(DS[700]), bytes(DS[755]), bytes(DS[756]), bytes(DS[760]), bytes(DS[761]), bytes(DS[765]), bytes(DS[766]), bytes(DS[770]), bytes(DS[771]), bytes(DS[775]), bytes(DS[776]), drops(DS[780]), drops(DS[781]), bytes(DS[784]), bytes(DS[789]), bytes(DS[794]), Additional Issues Remain.  Only showing first 20
08/03/2010 10:36:39 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine2/bin/spine, ARGS:  0 324]
08/03/2010 10:36:39 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine2/bin/spine, ARGS:  325 685]
08/03/2010 10:36:39 AM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine2/bin/spine, ARGS:  689 905]
Waiting on 2 of 3 pollers.
08/03/2010 10:36:54 AM - SYSTEM STATS: Time:15.2705 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3467 RRDsProcessed:2455

You will see that in this case, the sleep time is 21.64 seconds, but if you also review the time between the end of the first log message and the next spawn, you will see that it is much higher than expected.

Code: Select all

08/03/2010 10:35:25 AM - SYSTEM STATS: Time:38.3156 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3467 RRDsProcessed:2554
08/03/2010 10:36:39 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty.  Issues Found: 3348, Data Sources: bytes(DS[675]), 

Instead of the sleep time being ~21 seconds, it ends up being 74 seconds. So, that is your assignment. The code is good, but for some reason, there is a lag.

If on a VM, the usleep function may not be reliable. If plugin related, it could be associated with either the poller_top, or poller_bottom.

TheWitness