Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

An open discussion forum for obtaining help with Nagios Core. Nagios Core users of all experience levels are welcome here. Subforum have been created for the discussion of Nagios Core and Nagios Plugin development.

NOTE: The SourceForge.net mailing lists have been deprecated in favor of this forum in order to expedite support and provide additional features not available on the old mailing list.

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby jfrickson » Wed Feb 03, 2016 11:18 am

MalcolmPreen wrote:I'm a little confused, as send_nsca has an inbuilt timeout.... (which I have upped to 120s due to historic issues.... this can be reduced if needed).

Does it make any sense that send_nsca should go into a loop if the network it is using should fail as it is using it ? I would have thought the message would be lost, and the script would just continue after "timeout" seconds ??

Is there anything I can do to debug send_nsca ?
How should I best "kill" it, if the problem recurs in the same way ?


Hmm, very odd. Yes, it should time out.

I did some research, and so far I found two instances of alarm() being blocked. One is (or was) a bug in the NVidia proprietary driver, and one is (or was) a bug in tcp wrappers. So it is possible for another program to block signals in send_nsca.

Get the PID of send_nsca then do the following (replacing 9999 with the actual PID):
# cat /proc/9999/status | grep "^SigBlk"
And post the results.
Former Nagios Employee
jfrickson
Developer
 
Posts: 188
Joined: Wed Jul 22, 2015 9:58 am

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby MalcolmPreen » Wed Feb 03, 2016 11:40 am

Thanks... by way of interest... I've "caught" a live one (not hung.... but proof of concept), and see the following;

Code: Select all
PID=7761
  PID TTY          TIME CMD
7761 ?        00:00:00 send_nsca
Name:   send_nsca
State:  S (sleeping)
Tgid:   7761
Pid:    7761
PPid:   7760
TracerPid:      0
Uid:    500     500     500     500
Gid:    500     500     500     500
Utrace: 0
FDSize: 32
Groups: 500
VmPeak:     2420 kB
VmSize:     2388 kB
VmLck:         0 kB
VmHWM:       660 kB
VmRSS:       660 kB
VmData:      184 kB
VmStk:        92 kB
VmExe:        16 kB
VmLib:      2032 kB
VmPTE:        32 kB
VmSwap:        0 kB
Threads:        1
SigQ:   2/29661
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000001000
SigCgt: 0000000000002000
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: ffffffffffffffff
Cpus_allowed:   ff
Cpus_allowed_list:      0-7
Mems_allowed:   1
Mems_allowed_list:      0
voluntary_ctxt_switches:        2
nonvoluntary_ctxt_switches:     1


Obviously, that's not a hung one.... and I assume the above is as expected...

Will re-work the "kill" script, to capture this output should it recur...

Malcolm
MalcolmPreen
 
Posts: 63
Joined: Wed Jan 25, 2012 9:21 am

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby hsmith » Wed Feb 03, 2016 3:45 pm

Let us know how it goes with reworking the script.
Former Nagios Employee.
me.
User avatar
hsmith
Agent Smith
 
Posts: 3539
Joined: Thu Jul 30, 2015 11:09 am
Location: 127.0.0.1

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby MalcolmPreen » Thu Feb 04, 2016 5:21 am

Quick update:

Overnight we had an issue with the VPN set-up, which resulted in a number of the tablets losing their VPN connect and re-starting it....

This does appear to provoke the problem.... so it may be reproducible in a relatively controlled environment...

One interesting thing to note however, is that two of the tablets which are still running nagios 4.0.8 appeared to experience the same problem (one or more worker process goes busy... and nagios services at the "centre" start to go stale).

These are less available for "testing" but it is interesting (to me at least :-) ) that the problem does not appear restricted to 4.1.2-Pre1

Unfortunately, no more details are available at present... but I figured the above info might help (a bit!).

Malcolm

PS Update: another thing to note... whilst on 4.0.8 we see a similar pattern... (stale statuses etc), the "busy loop" is not "as busy".

To try to explain; under 4.1.2-Pre1 - the loop is hard... so much so that every service goes stale (suggesting that no nsca reports are getting through)
whilst with 4.0.8 - one of the worker processes loops as per 4.1.2-Pre1 - but nagios itself seems to continue.... which means that the problem is less serious (only a few reports don't run....) but also that it is harder to detect. (all services going stale is a helpful flag)

I don't know which scenario is going to be better to investigate.... but I can "almost" reproduce the problem in an "almost" controlled environment.
MalcolmPreen
 
Posts: 63
Joined: Wed Jan 25, 2012 9:21 am

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby MalcolmPreen » Thu Feb 04, 2016 11:20 am

Followup:

OK, we have established that we had a number of VPN failures last night (technically, the VPN didn't fail completely.... but the test for a failure reported that it had (the timeout was too short)) and the system is set to, upon vpn failure, to stop and re-start the vpn link.

Unfortunately (or maybe fortunately as we've collected some data!!), this resulted in a number of "busy loop" worker processes.

As previously advised, I coded a script to run the requested gdb -p commands, a few ps's out to a file.... and then kill -1 the "busy" process so that monitoring could continue.

In every case, the gdb output is identical (apart from addresses)

Code: Select all
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-83.el6)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "i686-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 1737
Reading symbols from /usr/local/nagios/bin/nagios...(no debugging symbols found)...done.
Reading symbols from /lib/libm.so.6...Reading symbols from /usr/lib/debug/lib/libm-2.12.so.debug...done.
done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib/libdl.so.2...Reading symbols from /usr/lib/debug/lib/libdl-2.12.so.debug...done.
done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/libc.so.6...Reading symbols from /usr/lib/debug/lib/libc-2.12.so.debug...done.
done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.2...Reading symbols from /usr/lib/debug/lib/ld-2.12.so.debug...done.
done.
Loaded symbols for /lib/ld-linux.so.2
0x0016d424 in __kernel_vsyscall ()
(gdb) #0  0x0016d424 in __kernel_vsyscall ()
#1  0x0041a8d3 in __read_nocancel () at ../sysdeps/unix/syscall-template.S:82
#2  0x080bd522 in ?? ()
#3  0x080bd680 in finish_job ()
#4  0x080bd4b5 in ?? ()
#5  0x080bd5c2 in ?? ()
#6  0x080bdcb3 in ?? ()
#7  0x080bad43 in iobroker_poll ()
#8  0x080be131 in enter_worker ()
#9  0x08058ec8 in main ()
(gdb) Detaching from program: /usr/local/nagios/bin/nagios, process 1737


The ps axlf varies.... for example, 4 ps's separated by sleep 60;
Code: Select all
0   500  1737  1726  20   0   3452   872 -      R    ?          3:14  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh
0   500  1737  1726  20   0   3452   872 -      R    ?          4:14  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh
0   500  1737  1726  20   0   3452   872 -      R    ?          5:14  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh
0   500  1737  1726  20   0   3452   872 -      R    ?          6:14  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh


In this example above.... there are no children.... but
Code: Select all
0   500  2423  2421  20   0   4044  1640 -      R    ?         46:03  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh
0   500  6513  2423  20   0      0     0 -      Z    ?          0:00  |   \_ [check_by_ssh] <defunct>
0   500 10537  2423  20   0      0     0 -      Z    ?          0:00  |   \_ [check_by_ssh] <defunct>

0   500  2423  2421  20   0   4044  1640 -      R    ?         47:03  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh
0   500  6513  2423  20   0      0     0 -      Z    ?          0:00  |   \_ [check_by_ssh] <defunct>
0   500 10537  2423  20   0      0     0 -      Z    ?          0:00  |   \_ [check_by_ssh] <defunct>


Apart from the fact that the CPU usages increases by 1 minute after a sleep 60, there appears to be no pattern.

Unfortunately, I didn't get the chance to include the
Code: Select all
cat /proc/XXXX/status
in the output... will get that added now....
MalcolmPreen
 
Posts: 63
Joined: Wed Jan 25, 2012 9:21 am

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby MalcolmPreen » Thu Feb 04, 2016 11:31 am

Correction:

I did include the cat of the /proc/XXXX/status - but only if it found an active send_nsca process.... which only happened once.... and by the time the cat command ran, the process had terminated.

As it appears that send_nsca is no longer the cause of the problem - is there any mileage in collecting this output.... but for the "busy loop" process ?

Any advice, greatly appreciated, Malcolm
MalcolmPreen
 
Posts: 63
Joined: Wed Jan 25, 2012 9:21 am

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby jfrickson » Thu Feb 04, 2016 12:07 pm

MalcolmPreen wrote:Correction:

I did include the cat of the /proc/XXXX/status - but only if it found an active send_nsca process.... which only happened once.... and by the time the cat command ran, the process had terminated.

As it appears that send_nsca is no longer the cause of the problem - is there any mileage in collecting this output.... but for the "busy loop" process ?


A cat of /proc/XXXX/status would be interesting to see on the worker that's stuck in the loop. It sounds like any further checks on send_nsca will not help.

You have a great mystery going here. I'm going to lose sleep over it if we can't find out what's going on! :shock:
Former Nagios Employee
jfrickson
Developer
 
Posts: 188
Joined: Wed Jul 22, 2015 9:58 am

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby MalcolmPreen » Thu Feb 04, 2016 12:23 pm

the capture of /proc/$PID/status is now included...

If it survives overnight, I'll work on a "reproduction" in a controlled environment tomorrow assuming I get some time....

Thanks, Malcolm
MalcolmPreen
 
Posts: 63
Joined: Wed Jan 25, 2012 9:21 am

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby hsmith » Thu Feb 04, 2016 5:16 pm

Let us know when you have a chance.

Thanks!
Former Nagios Employee.
me.
User avatar
hsmith
Agent Smith
 
Posts: 3539
Joined: Thu Jul 30, 2015 11:09 am
Location: 127.0.0.1

Re: Problem with Nagios 4.1.2-Pre1 (nagios "busy loop")

Postby MalcolmPreen » Fri Feb 05, 2016 11:16 am

OK... controlled re-production in place.

In summary... if the VPN (openconnect) terminates... (or is deliberately terminated by me), there is code in place to detect this failure.... and re-start the link

After this (not sure at present if it is when the vpn fails... or when it recovers... or somewhere in between), I can see that one worker process and also the nagios core (nagios -d) are in a busy loop. Initially, the fourth column of ps -ef remains at 0.... until about 10-15 minutes have elapsed...

My detection script is looking for non-zero in the fourth column, so only kicks in after it goes non-zero (I'll work on improving this.... so it can detect the problem quicker... and thus have less affect on the customer).

The /proc/PID/status from the busy worker process is;
Code: Select all
Name:   nagios
State:  R (running)
Tgid:   1732
Pid:    1732
PPid:   1726
TracerPid:      0
Uid:    500     500     500     500
Gid:    500     500     500     500
Utrace: 0
FDSize: 256
Groups: 500
VmPeak:     4488 kB
VmSize:     3440 kB
VmLck:         0 kB
VmHWM:      1960 kB
VmRSS:      1040 kB
VmData:      812 kB
VmStk:        88 kB
VmExe:       596 kB
VmLib:      1896 kB
VmPTE:        24 kB
VmSwap:        0 kB
Threads:        1
SigQ:   2/29661
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000001000
SigCgt: 0000000000010000
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: ffffffffffffffff
Cpus_allowed:   ff
Cpus_allowed_list:      0-7
Mems_allowed:   1
Mems_allowed_list:      0
voluntary_ctxt_switches:        73974
nonvoluntary_ctxt_switches:     121764


And the ps axlf every minute for 4 minutes shows;
Code: Select all
$ grep "nagios -d" /tmp/*1732
1   500  1726     1  20   0  21364  3492 -      Rs   ?         26:26 /usr/local/nagios/bin/nagios -d /usr/local/nagios/etc/nagios.cfg
1   500  1726     1  20   0  21364  3492 -      Rs   ?         27:26 /usr/local/nagios/bin/nagios -d /usr/local/nagios/etc/nagios.cfg
1   500  1726     1  20   0  21364  3492 -      Rs   ?         28:26 /usr/local/nagios/bin/nagios -d /usr/local/nagios/etc/nagios.cfg
1   500  1726     1  20   0  21364  3492 -      Rs   ?         29:26 /usr/local/nagios/bin/nagios -d /usr/local/nagios/etc/nagios.cfg
$ grep 1732 /tmp/*1732
Attaching to process 1732
(gdb) Detaching from program: /usr/local/nagios/bin/nagios, process 1732
0   500  1732  1726  20   0   3440  1040 -      R    ?         19:19  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh
0   500  1732  1726  20   0   3440  1040 -      R    ?         20:19  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh
0   500  1732  1726  20   0   3440  1040 -      R    ?         21:19  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh
0   500  1732  1726  20   0   3440  1040 -      R    ?         22:19  \_ /usr/local/nagios/bin/nagios --worker /usr/local/nagios/var/rw/nagios.qh


By my interpretation 1 minute of CPU time per minute = busy loop !!

My next plan... is to check the status file BEFORE reproducing the error... and see if it changes... and also the same before/after for the nagios -d controller process.

The "easy" solution is to stop the VPN from failing !!

Any further suggestions ?

Malcolm

PS quick advanced notice - I will be on vacation from 12-22 February inclusive... so I won't be providing updates... during those dates.
MalcolmPreen
 
Posts: 63
Joined: Wed Jan 25, 2012 9:21 am

PreviousNext

Return to Nagios Core

Who is online

Users browsing this forum: No registered users and 28 guests