Cacti log file reporting "Poller Output Table not Empty

[TheWitness]

Show me a list of your installed plugins. Then disable one at a time and see if the problem corrects itself. Don't worry about MacTrack. I know that one and it does not block with the poller_top and poller_bottom hooks. Also, let me know if this is a VM.

TheWitness

[philipz]

These are the plugins installed:
Monitor 0.8.2
Mactrack 2.8
Discovery 0.8.5
Weathermap 0.97a

I have disabled them all, just to see if that will help. If so, I'll enable them one by one.

It is not a VM btw, FreeBSD 6.2-RELEASE.
Will let you know the result.

[philipz]

Disabling the plugins didn't help, I still get the timeout issue.
I will change spine to cmd, see if that makes a difference.

[philipz]

No difference there either.

Due to some MySQL errors I used spine 0.8.7e instead of 0.8.7g. I will compile 0.8.7g again and see where I get with that spine version but I don't think it is related since cmd.php produces the same error.

[philipz]

This is part of the debugging with spine0.8.7g:

08/03/2010 05:36:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:36:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:36:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:36:56 PM - SYSTEM STATS: Time:0.3400 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0
08/03/2010 05:36:56 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/03/2010 05:36:56 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine-0.8.7g/spine, ARGS: 683 906]
08/03/2010 05:36:56 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine-0.8.7g/spine, ARGS: 357 682]
08/03/2010 05:36:56 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine-0.8.7g/spine, ARGS: 0 356]
08/03/2010 05:36:56 PM - POLLER: Poller[0] WARNING: There are '3' detected as overrunning a polling process, please investigate
08/03/2010 05:36:56 PM - POLLER: Poller[0] -1280849697.99 seconds
08/03/2010 05:36:56 PM - SYSTEM STATS: Time:178.5129 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0
08/03/2010 05:36:56 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/03/2010 05:35:58 PM - SYSTEM STATS: Time:0.3121 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0
08/03/2010 05:35:58 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/03/2010 05:35:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:35:58 PM - POLLER: Poller[0] WARNING: There are '1' detected as overrunning a polling process, please investigate
08/03/2010 05:35:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:35:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:34:59 PM - SYSTEM STATS: Time:1.3119 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0
08/03/2010 05:34:59 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/03/2010 05:34:58 PM - SYSTEM STATS: Time:120.4691 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0

Phil

[gandalf]

So this is 1 min polling?
If yes, Larry may know the required workaround for that.
R.

[philipz]

So this is 1 min polling?
If yes, Larry may know the required workaround for that.
R.

it is 1 minute polling. Would be cool to have a workaround... Too long without our monitoring already

[TheWitness]

The current workaround is 1 minute cron, 1 minute polling.

TheWitness

[TheWitness]

This is part of the debugging with spine0.8.7g:

08/03/2010 05:36:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:36:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:36:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:36:56 PM - SYSTEM STATS: Time:0.3400 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0
08/03/2010 05:36:56 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/03/2010 05:36:56 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine-0.8.7g/spine, ARGS: 683 906]
08/03/2010 05:36:56 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine-0.8.7g/spine, ARGS: 357 682]
08/03/2010 05:36:56 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine-0.8.7g/spine, ARGS: 0 356]
08/03/2010 05:36:56 PM - POLLER: Poller[0] WARNING: There are '3' detected as overrunning a polling process, please investigate
08/03/2010 05:36:56 PM - POLLER: Poller[0] -1280849697.99 seconds
08/03/2010 05:36:56 PM - SYSTEM STATS: Time:178.5129 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0
08/03/2010 05:36:56 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/03/2010 05:35:58 PM - SYSTEM STATS: Time:0.3121 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0
08/03/2010 05:35:58 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/03/2010 05:35:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:35:58 PM - POLLER: Poller[0] WARNING: There are '1' detected as overrunning a polling process, please investigate
08/03/2010 05:35:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:35:58 PM - SPINE: Poller[0] ERROR: Spine Timed Out While Processing Hosts Internal
08/03/2010 05:34:59 PM - SYSTEM STATS: Time:1.3119 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0
08/03/2010 05:34:59 PM - POLLER: Poller[0] Maximum runtime of 298 seconds exceeded. Exiting.
08/03/2010 05:34:58 PM - SYSTEM STATS: Time:120.4691 Method:spine Processes:3 Threads:20 Hosts:562 HostsPerProcess:188 DataSources:3659 RRDsProcessed:0

Phil

I need output from the poller run manually in debug. Simply providing the log does not give enough information for this test. However, it looks like you are not running the latest file from the bug report.

TheWitness

[philipz]

Here is the debug.
As far as I know, I am running all latest versions and all patches.
PIA is installed but no plugins enabled. I installed poller-pia.php from bug 1815 as suggested.

Thanks,

Phil

[TheWitness]

Here is a rollup PIA beta.

http://forums.cacti.net/viewtopic.php?p=196473#196473

I am thinking that the usleep() function has issues. However, I'm short of cycles at the moment.

TheWitness

[philipz]

Latest debug is a short one.
It still gives me the "Spine Timed Out While Processing Hosts Internal" error.

[TheWitness]

Use the SVN of spine. The release has a mutex locking issue that will freeze the code.

TheWitness

[philipz]

I have compiled the latest spine from svn (at least I hope it is the latest - not sure how to check since they all mention 0.8.7g and I'm not familiar with svn).
Same errors/timeouts still occur; see debug.txt
Is there an indication that PIA is the source of the problem? If so, I am happy (not really, but anyway) to "uninstall" PIA to have a working system again...

[TheWitness]

Did you install PIA 2.9 Beta? I have reports from numerous issues that the problems have been fixed. However, if you have something running either in poller_top or poller_bottom hooks from your plugins, that will affect things. This is my guess.

Some plugin developers insist on not backgrounding tasks which can lead to this behavior.

Here is the link: http://forums.cacti.net/viewtopic.php?p=196406#196406

TheWitness