eventhandler timeout 3.0.4

[Michael Streb]

Hi,

I already posted this issue a while ago, see
"[Nagios-devel] blocking character of event_handlers" on the list.

Regards,

Michael


Am 29.10.08 14:53 schrieb "Sven Nierlein" unter <sven at consol.de>:

> Iretried this test with the 3.0.4 which resulted in the same behavior.
> 
> I installed a fresh installation from the sources, with just one
> servicecheck.
> 
> Nagios works fine till the eventhandler has to be executed:
> 
> nagios.log:
>> [1225287417] Nagios 3.0.4 starting... (PID=2345)
>> [1225287417] Local time is Wed Oct 29 14:36:57 CET 2008
>> [1225287417] LOG VERSION: 2.0
>> [1225287417] Finished daemonizing... (New PID=2346)
>> [1225287547] SERVICE ALERT: localhost;test;CRITICAL;SOFT;1;(null)
>> [1225287547] SERVICE EVENT HANDLER:
>> localhost;test;(null);(null);(null);sleep
> 
> nagios.debug:
>> [1225287547.230915] [2048.1] [pid=2346]   Done.  Final output:
>> 'SERVICE ALERT: localhost;test;CRITICAL;SOFT;1;(null)'
>> [1225287547.230921] [2048.1] [pid=2346] **** END MACRO PROCESSING
>> *************
>> [1225287547.231080] [064.1] [pid=2346] Making callbacks (type 9)...
>> [1225287547.231091] [001.0] [pid=2346] handle_service_event()
>> [1225287547.231098] [064.1] [pid=2346] Making callbacks (type 30)...
>> [1225287547.231111] [001.0] [pid=2346] run_global_service_event_handler()
>> [1225287547.231118] [001.0] [pid=2346] run_service_event_handler()
>> [1225287547.231125] [016.1] [pid=2346] Running event handler for
>> service 'test' on host 'localhost'...
>> [1225287547.231136] [064.1] [pid=2346] Making callbacks (type 11)...
>> [1225287547.231155] [001.0] [pid=2346] get_raw_command_line()
>> [1225287547.231163] [2320.2] [pid=2346] Raw Command Input: /bin/bash
>> -c "sleep 300"
>> [1225287547.231170] [2320.2] [pid=2346] Expanded Command Output:
>> /bin/bash -c "sleep 300"
>> [1225287547.231177] [016.2] [pid=2346] Raw service event handler
>> command line: /bin/bash -c "sleep 300"
>> [1225287547.231184] [001.0] [pid=2346] process_macros()
>> [1225287547.231190] [2048.1] [pid=2346] **** BEGIN MACRO PROCESSING
>> ***********
>> [1225287547.231197] [2048.1] [pid=2346] Processing: '/bin/bash -c
>> "sleep 300"'
>> [1225287547.231203] [2048.2] [pid=2346]   Processing part: '/bin/bash
>> -c "sleep 300"'
>> [1225287547.231211] [2048.2] [pid=2346]   Not currently in macro.
>> Running output (24): '/bin/bash -c "sleep 300"'
>> [1225287547.231218] [2048.1] [pid=2346]   Done.  Final output:
>> '/bin/bash -c "sleep 300"'
>> [1225287547.231234] [2048.1] [pid=2346] **** END MACRO PROCESSING
>> *************
>> [1225287547.231241] [016.2] [pid=2346] Processed service event handler
>> command line: /bin/bash -c "sleep 300"
>> [1225287547.231327] [064.1] [pid=2346] Making callbacks (type 9)...
>> [1225287547.231336] [001.0] [pid=2346] my_system()
>> [1225287547.231344] [256.1] [pid=2346] Running command '/bin/bash -c
>> "sleep 300"'...
>> [1225287547.231367] [064.1] [pid=2346] Making callbacks (type 10)...
>> [1225287547.231967] [001.0] [pid=2451] process_macros()
>> [1225287547.231997] [001.0] [pid=2451] process_macros()
>> [1225287547.232013] [001.0] [pid=2451] process_macros()
>> [1225287547.232028] [001.0] [pid=2451] process_macros()
>> [1225287547.232042] [001.0] [pid=2451] process_macros()
>> [1225287547.232056] [001.0] [pid=2451] process_macros()
>> [1225287551.231246] [016.2] [pid=2448] Moving temp check result file
>> '/tmp/nagios/var/spool/checkresults/check13kIOP' to queue file
>> '/tmp/nagios/var/spool/checkresults/cn2NyLo'...
>> 
>> *** 300sec gap ***
>> 
>> [1225287847.239230] [256.1] [pid=2346] Execution time=30.001 sec
>> , early timeout=0, result=2[1225287847.239309] [064.1] [pid=2346]
>> Making callbacks (type 10)...
>> [1225287847.239332] [064.1] [pid=2346] Making callbacks (type 11)...
>> [1225287847.239341] [001.0] [pid=2346] check_for_external_commands()
>> [1225287847.239350] [064.1] [pid=2346] Making callbacks (type 18)...
>> [1225287847.239376] [016.1] [pid=2346] Rescheduling next check of
>> service at Wed Oct 29 14:39:57 2008
>> [1225287847.239386] [001.0] [pid=2346] get_next_valid_time()
>> [1225287847.239394] [001.0] [pid=2346] check_time_against_period()
> 
> So Nagios does nothing during the execution of eventhandler. I gues the
> reason is because the eventhandler is executed by the main nagios
> process (look at the pid). During the 300seconds sleep, Nagios takes
> 100% cpu.
> 
> 
> -------------------------------------------------------------------------
> This SF.Net email is sponsored by the Moblin Your Move Developer's challenge
> Build the coolest Linux based applications with Moblin SDK & win great prizes
> Grand prize is a trip for two to an Open Source event anywhere in the world
> http://moblin-contest.org/redirect.php?banner_id=100&url=/
> _______________________________________________
> Nagios-devel mailing list
> Nagios-devel at lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/nagios-devel

-- 
Michael Streb
Managing Consultant

NETWAYS GmbH | Deutschherrnstr. 15-19 | D-90429 Nürnberg
Tel: +49 911 92885-0 | Fax: +49 911 92885-77
GF: Julian Hein | AG Nürnberg HRB18461

http://www.netways.de | michael.streb at netways.de

** NETWAYS Nagios Training - http://www.netways.de/training **


-------------------------------------------------------------------------
This SF.Net email is sponsored by the Moblin Your Move Developer's challenge
Build the coolest Linux based applications with Moblin SDK & win great prizes
Grand prize is a trip for two to an Open Source event anywhere in the world
http://moblin-contest.org/redirect.php?banner_id=100&url=/