[1225287547.230664] [2048.1] [pid=2346] **** BEGIN MACRO PROCESSING ***********
[1225287547.230671] [2048.1] [pid=2346] Processing: 'SERVICE ALERT: localhost;test;$SERVICESTATE$;$SERVICESTATETYPE$;$SERVICEATTEMPT$;(null)'
[1225287547.230678] [2048.2] [pid=2346]   Processing part: 'SERVICE ALERT: localhost;test;'
[1225287547.230688] [2048.2] [pid=2346]   Not currently in macro.  Running output (30): 'SERVICE ALERT: localhost;test;'
[1225287547.230695] [2048.2] [pid=2346]   Processing part: 'SERVICESTATE'
[1225287547.230723] [2048.2] [pid=2346]   macro_x[4] (SERVICESTATE) match.
[1225287547.230733] [2048.2] [pid=2346]   Processed 'SERVICESTATE', Clean Options: 0, Free: 1
[1225287547.230741] [2048.2] [pid=2346]   Processed 'SERVICESTATE', Clean Options: 0, Free: 1
[1225287547.230748] [2048.2] [pid=2346]   Cleaning options: global=0, local=0, effective=0
[1225287547.230756] [2048.2] [pid=2346]   Uncleaned macro.  Running output (38): 'SERVICE ALERT: localhost;test;CRITICAL'
[1225287547.230763] [2048.2] [pid=2346]   Just finished macro.  Running output (38): 'SERVICE ALERT: localhost;test;CRITICAL'
[1225287547.230770] [2048.2] [pid=2346]   Processing part: ';'
[1225287547.230777] [2048.2] [pid=2346]   Not currently in macro.  Running output (39): 'SERVICE ALERT: localhost;test;CRITICAL;'
[1225287547.230784] [2048.2] [pid=2346]   Processing part: 'SERVICESTATETYPE'
[1225287547.230792] [2048.2] [pid=2346]   macro_x[42] (SERVICESTATETYPE) match.
[1225287547.230799] [2048.2] [pid=2346]   Processed 'SERVICESTATETYPE', Clean Options: 0, Free: 1
[1225287547.230807] [2048.2] [pid=2346]   Processed 'SERVICESTATETYPE', Clean Options: 0, Free: 1
[1225287547.230814] [2048.2] [pid=2346]   Cleaning options: global=0, local=0, effective=0
[1225287547.230821] [2048.2] [pid=2346]   Uncleaned macro.  Running output (43): 'SERVICE ALERT: localhost;test;CRITICAL;SOFT'
[1225287547.230828] [2048.2] [pid=2346]   Just finished macro.  Running output (43): 'SERVICE ALERT: localhost;test;CRITICAL;SOFT'
[1225287547.230835] [2048.2] [pid=2346]   Processing part: ';'
[1225287547.230842] [2048.2] [pid=2346]   Not currently in macro.  Running output (44): 'SERVICE ALERT: localhost;test;CRITICAL;SOFT;'
[1225287547.230849] [2048.2] [pid=2346]   Processing part: 'SERVICEATTEMPT'
[1225287547.230856] [2048.2] [pid=2346]   macro_x[6] (SERVICEATTEMPT) match.
[1225287547.230865] [2048.2] [pid=2346]   Processed 'SERVICEATTEMPT', Clean Options: 0, Free: 1
[1225287547.230872] [2048.2] [pid=2346]   Processed 'SERVICEATTEMPT', Clean Options: 0, Free: 1
[1225287547.230880] [2048.2] [pid=2346]   Cleaning options: global=0, local=0, effective=0
[1225287547.230887] [2048.2] [pid=2346]   Uncleaned macro.  Running output (45): 'SERVICE ALERT: localhost;test;CRITICAL;SOFT;1'
[1225287547.230894] [2048.2] [pid=2346]   Just finished macro.  Running output (45): 'SERVICE ALERT: localhost;test;CRITICAL;SOFT;1'
[1225287547.230901] [2048.2] [pid=2346]   Processing part: ';(null)'
[1225287547.230908] [2048.2] [pid=2346]   Not currently in macro.  Running output (53): 'SERVICE ALERT: localhost;test;CRITICAL;SOFT;1;(null)'
[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()