VMware Plugin Issue

[benjohns]

Ok, I set the debug level to 1 and restarted Nagios. Then I disabled all monitored hosts & services other than the one CPU check that uses this plugin to isolate the relevant data to the debug file.

I started a tail of the debug file, then clicked on 'Force an immediate check' for the "CPU Usage for VMHost". The service check still times out with the following message: (Service check timed out after 180.07 seconds)

Here is the dump from the file from just before I clicked to force a check to when it returned a timeout:

# tail -f /usr/local/nagios/var/nagios.debug

Code: Select all

[1520449434.974623] [001.0] [pid=21572] save_status_data()
[1520449434.977531] [001.0] [pid=21572] handle_timed_event() end
[1520449434.977552] [001.0] [pid=21572] reschedule_event()
[1520449434.977558] [001.0] [pid=21572] add_event()
[1520449434.977579] [001.0] [pid=21572] handle_timed_event() start
[1520449434.977590] [001.0] [pid=21572] reap_check_results() start
[1520449434.977627] [001.0] [pid=21572] reap_check_results() end
[1520449434.977633] [001.0] [pid=21572] handle_timed_event() end
[1520449434.977638] [001.0] [pid=21572] reschedule_event()
[1520449434.977642] [001.0] [pid=21572] add_event()
[1520449444.975668] [001.0] [pid=21572] handle_timed_event() start
[1520449444.975838] [001.0] [pid=21572] save_status_data()
[1520449444.987024] [001.0] [pid=21572] handle_timed_event() end
[1520449444.987046] [001.0] [pid=21572] reschedule_event()
[1520449444.987052] [001.0] [pid=21572] add_event()
[1520449444.987075] [001.0] [pid=21572] handle_timed_event() start
[1520449444.987086] [001.0] [pid=21572] reap_check_results() start
[1520449444.987117] [001.0] [pid=21572] reap_check_results() end
[1520449444.987139] [001.0] [pid=21572] handle_timed_event() end
[1520449444.987148] [001.0] [pid=21572] reschedule_event()
[1520449444.987153] [001.0] [pid=21572] add_event()
[1520449444.987174] [001.0] [pid=21572] handle_timed_event() start
[1520449444.987196] [001.0] [pid=21572] adjust_check_scheduling() start
[1520449444.987222] [001.0] [pid=21572] handle_timed_event() end
[1520449444.987240] [001.0] [pid=21572] reschedule_event()
[1520449444.987247] [001.0] [pid=21572] add_event()
[1520449444.987267] [001.0] [pid=21572] handle_timed_event() start
[1520449444.987292] [001.0] [pid=21572] process_host_perfdata_file()
[1520449444.987319] [001.0] [pid=21572] get_raw_command_line_r()
[1520449444.987350] [001.0] [pid=21572] process_macros_r()
[1520449444.987390] [001.0] [pid=21572] my_system_r()
[1520449444.991763] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449444.991840] [001.0] [pid=21572] handle_timed_event() end
[1520449444.991856] [001.0] [pid=21572] reschedule_event()
[1520449444.991860] [001.0] [pid=21572] add_event()
[1520449444.991881] [001.0] [pid=21572] handle_timed_event() start
[1520449444.991902] [001.0] [pid=21572] process_service_perfdata_file()
[1520449444.991908] [001.0] [pid=21572] get_raw_command_line_r()
[1520449444.991937] [001.0] [pid=21572] process_macros_r()
[1520449444.991957] [001.0] [pid=21572] my_system_r()
[1520449444.995828] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449444.995847] [001.0] [pid=21572] handle_timed_event() end
[1520449444.995860] [001.0] [pid=21572] reschedule_event()
[1520449444.995864] [001.0] [pid=21572] add_event()
[1520449446.187459] [001.0] [pid=21572] process_external_command1()
[1520449446.187535] [001.0] [pid=21572] process_external_command2()
[1520449446.187548] [001.0] [pid=21572] schedule_service_check()
[1520449446.187579] [001.0] [pid=21572] add_event()
[1520449446.187663] [001.0] [pid=21572] handle_timed_event() start
[1520449446.187675] [001.0] [pid=21572] run_scheduled_service_check() start
[1520449446.187683] [001.0] [pid=21572] run_async_service_check()
[1520449446.187688] [001.0] [pid=21572] check_service_check_viability()
[1520449446.187698] [001.0] [pid=21572] get_raw_command_line_r()
[1520449446.187707] [001.0] [pid=21572] process_macros_r()
[1520449446.187715] [001.0] [pid=21572] process_macros_r()
[1520449446.187721] [001.0] [pid=21572] process_macros_r()
[1520449446.187727] [001.0] [pid=21572] process_macros_r()
[1520449446.187898] [001.0] [pid=21572] macros_to_kvv()
[1520449446.188147] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449446.188194] [001.0] [pid=21572] handle_timed_event() end
[1520449454.976324] [001.0] [pid=21572] handle_timed_event() start
[1520449454.976498] [001.0] [pid=21572] save_status_data()
[1520449454.979681] [001.0] [pid=21572] handle_timed_event() end
[1520449454.979698] [001.0] [pid=21572] reschedule_event()
[1520449454.979703] [001.0] [pid=21572] add_event()
[1520449454.979722] [001.0] [pid=21572] handle_timed_event() start
[1520449454.979733] [001.0] [pid=21572] reap_check_results() start
[1520449454.979769] [001.0] [pid=21572] reap_check_results() end
[1520449454.979774] [001.0] [pid=21572] handle_timed_event() end
[1520449454.979780] [001.0] [pid=21572] reschedule_event()
[1520449454.979784] [001.0] [pid=21572] add_event()
[1520449459.975124] [001.0] [pid=21572] handle_timed_event() start
[1520449459.975239] [001.0] [pid=21572] process_service_perfdata_file()
[1520449459.975248] [001.0] [pid=21572] get_raw_command_line_r()
[1520449459.975257] [001.0] [pid=21572] process_macros_r()
[1520449459.975294] [001.0] [pid=21572] my_system_r()
[1520449459.979576] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449459.979600] [001.0] [pid=21572] handle_timed_event() end
[1520449459.979615] [001.0] [pid=21572] reschedule_event()
[1520449459.979634] [001.0] [pid=21572] add_event()
[1520449459.979665] [001.0] [pid=21572] handle_timed_event() start
[1520449459.979680] [001.0] [pid=21572] process_host_perfdata_file()
[1520449459.979686] [001.0] [pid=21572] get_raw_command_line_r()
[1520449459.979694] [001.0] [pid=21572] process_macros_r()
[1520449459.979713] [001.0] [pid=21572] my_system_r()
[1520449459.983106] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449459.983178] [001.0] [pid=21572] handle_timed_event() end
[1520449459.983195] [001.0] [pid=21572] reschedule_event()
[1520449459.983199] [001.0] [pid=21572] add_event()
[1520449464.975336] [001.0] [pid=21572] handle_timed_event() start
[1520449464.975445] [001.0] [pid=21572] save_status_data()
[1520449464.982921] [001.0] [pid=21572] handle_timed_event() end
[1520449464.982946] [001.0] [pid=21572] reschedule_event()
[1520449464.982951] [001.0] [pid=21572] add_event()
[1520449464.982972] [001.0] [pid=21572] handle_timed_event() start
[1520449464.982990] [001.0] [pid=21572] reap_check_results() start
[1520449464.983104] [001.0] [pid=21572] reap_check_results() end
[1520449464.983117] [001.0] [pid=21572] handle_timed_event() end
[1520449464.983123] [001.0] [pid=21572] reschedule_event()
[1520449464.983127] [001.0] [pid=21572] add_event()
[1520449474.975387] [001.0] [pid=21572] handle_timed_event() start
[1520449474.975542] [001.0] [pid=21572] save_status_data()
[1520449474.991052] [001.0] [pid=21572] handle_timed_event() end
[1520449474.991072] [001.0] [pid=21572] reschedule_event()
[1520449474.991084] [001.0] [pid=21572] add_event()
[1520449474.991106] [001.0] [pid=21572] handle_timed_event() start
[1520449474.991117] [001.0] [pid=21572] reap_check_results() start
[1520449474.991144] [001.0] [pid=21572] reap_check_results() end
[1520449474.991155] [001.0] [pid=21572] handle_timed_event() end
[1520449474.991161] [001.0] [pid=21572] reschedule_event()
[1520449474.991165] [001.0] [pid=21572] add_event()
[1520449474.991178] [001.0] [pid=21572] handle_timed_event() start
[1520449474.991188] [001.0] [pid=21572] process_host_perfdata_file()
[1520449474.991201] [001.0] [pid=21572] get_raw_command_line_r()
[1520449474.991211] [001.0] [pid=21572] process_macros_r()
[1520449474.991234] [001.0] [pid=21572] my_system_r()
[1520449474.995243] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449474.995314] [001.0] [pid=21572] handle_timed_event() end
[1520449474.995334] [001.0] [pid=21572] reschedule_event()
[1520449474.995339] [001.0] [pid=21572] add_event()
[1520449474.995359] [001.0] [pid=21572] handle_timed_event() start
[1520449474.995372] [001.0] [pid=21572] check_service_result_freshness()
[1520449474.995381] [001.0] [pid=21572] handle_timed_event() end
[1520449474.995386] [001.0] [pid=21572] reschedule_event()
[1520449474.995390] [001.0] [pid=21572] add_event()
[1520449474.995401] [001.0] [pid=21572] handle_timed_event() start
[1520449474.995415] [001.0] [pid=21572] process_service_perfdata_file()
[1520449474.995421] [001.0] [pid=21572] get_raw_command_line_r()
[1520449474.995429] [001.0] [pid=21572] process_macros_r()
[1520449474.995446] [001.0] [pid=21572] my_system_r()
[1520449474.998868] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449474.998891] [001.0] [pid=21572] handle_timed_event() end
[1520449474.998905] [001.0] [pid=21572] reschedule_event()
[1520449474.998909] [001.0] [pid=21572] add_event()
[1520449474.998929] [001.0] [pid=21572] handle_timed_event() start
[1520449474.998940] [001.0] [pid=21572] adjust_check_scheduling() start
[1520449474.998949] [001.0] [pid=21572] handle_timed_event() end
[1520449474.998963] [001.0] [pid=21572] reschedule_event()
[1520449474.999084] [001.0] [pid=21572] add_event()
[1520449474.999102] [001.0] [pid=21572] handle_timed_event() start
[1520449474.999116] [001.0] [pid=21572] check_for_orphaned_hosts()
[1520449474.999122] [001.0] [pid=21572] check_for_orphaned_services()
[1520449474.999127] [001.0] [pid=21572] handle_timed_event() end
[1520449474.999131] [001.0] [pid=21572] reschedule_event()
[1520449474.999135] [001.0] [pid=21572] add_event()
[1520449484.975356] [001.0] [pid=21572] handle_timed_event() start
[1520449484.975499] [001.0] [pid=21572] save_status_data()
[1520449484.982596] [001.0] [pid=21572] handle_timed_event() end
[1520449484.982619] [001.0] [pid=21572] reschedule_event()
[1520449484.982625] [001.0] [pid=21572] add_event()
[1520449484.982647] [001.0] [pid=21572] handle_timed_event() start
[1520449484.982680] [001.0] [pid=21572] reap_check_results() start
[1520449484.982714] [001.0] [pid=21572] reap_check_results() end
[1520449484.982726] [001.0] [pid=21572] handle_timed_event() end
[1520449484.982731] [001.0] [pid=21572] reschedule_event()
[1520449484.982737] [001.0] [pid=21572] add_event()
[1520449489.974791] [001.0] [pid=21572] handle_timed_event() start
[1520449489.974904] [001.0] [pid=21572] process_host_perfdata_file()
[1520449489.974915] [001.0] [pid=21572] get_raw_command_line_r()
[1520449489.974939] [001.0] [pid=21572] process_macros_r()
[1520449489.974976] [001.0] [pid=21572] my_system_r()
[1520449489.979626] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449489.979723] [001.0] [pid=21572] handle_timed_event() end
[1520449489.979739] [001.0] [pid=21572] reschedule_event()
[1520449489.979744] [001.0] [pid=21572] add_event()
[1520449489.979782] [001.0] [pid=21572] handle_timed_event() start
[1520449489.979793] [001.0] [pid=21572] process_service_perfdata_file()
[1520449489.979798] [001.0] [pid=21572] get_raw_command_line_r()
[1520449489.979806] [001.0] [pid=21572] process_macros_r()
[1520449489.979823] [001.0] [pid=21572] my_system_r()
[1520449489.984469] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449489.984494] [001.0] [pid=21572] handle_timed_event() end
[1520449489.984512] [001.0] [pid=21572] reschedule_event()
[1520449489.984538] [001.0] [pid=21572] add_event()
[1520449494.975475] [001.0] [pid=21572] handle_timed_event() start
[1520449494.975631] [001.0] [pid=21572] save_status_data()
[1520449494.981507] [001.0] [pid=21572] handle_timed_event() end
[1520449494.981531] [001.0] [pid=21572] reschedule_event()
[1520449494.981537] [001.0] [pid=21572] add_event()
[1520449494.981560] [001.0] [pid=21572] handle_timed_event() start
[1520449494.981571] [001.0] [pid=21572] reap_check_results() start
[1520449494.981601] [001.0] [pid=21572] reap_check_results() end
[1520449494.981607] [001.0] [pid=21572] handle_timed_event() end
[1520449494.981622] [001.0] [pid=21572] reschedule_event()
[1520449494.981688] [001.0] [pid=21572] add_event()
[1520449504.975394] [001.0] [pid=21572] handle_timed_event() start
[1520449504.975551] [001.0] [pid=21572] save_status_data()
[1520449504.980865] [001.0] [pid=21572] handle_timed_event() end
[1520449504.980890] [001.0] [pid=21572] reschedule_event()
[1520449504.980896] [001.0] [pid=21572] add_event()
[1520449504.980921] [001.0] [pid=21572] handle_timed_event() start
[1520449504.980964] [001.0] [pid=21572] reap_check_results() start
[1520449504.980991] [001.0] [pid=21572] reap_check_results() end
[1520449504.981001] [001.0] [pid=21572] handle_timed_event() end
[1520449504.981006] [001.0] [pid=21572] reschedule_event()
[1520449504.981011] [001.0] [pid=21572] add_event()
[1520449504.981038] [001.0] [pid=21572] handle_timed_event() start
[1520449504.981049] [001.0] [pid=21572] process_service_perfdata_file()
[1520449504.981056] [001.0] [pid=21572] get_raw_command_line_r()
[1520449504.981077] [001.0] [pid=21572] process_macros_r()
[1520449504.981099] [001.0] [pid=21572] my_system_r()
[1520449504.985778] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449504.985817] [001.0] [pid=21572] handle_timed_event() end
[1520449504.985837] [001.0] [pid=21572] reschedule_event()
[1520449504.985844] [001.0] [pid=21572] add_event()
[1520449504.985874] [001.0] [pid=21572] handle_timed_event() start
[1520449504.985891] [001.0] [pid=21572] process_host_perfdata_file()
[1520449504.985904] [001.0] [pid=21572] get_raw_command_line_r()
[1520449504.985915] [001.0] [pid=21572] process_macros_r()
[1520449504.985942] [001.0] [pid=21572] my_system_r()
[1520449504.990364] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449504.990439] [001.0] [pid=21572] handle_timed_event() end
[1520449504.990462] [001.0] [pid=21572] reschedule_event()
[1520449504.990467] [001.0] [pid=21572] add_event()
[1520449504.990488] [001.0] [pid=21572] handle_timed_event() start
[1520449504.990502] [001.0] [pid=21572] adjust_check_scheduling() start
[1520449504.990511] [001.0] [pid=21572] handle_timed_event() end
[1520449504.990516] [001.0] [pid=21572] reschedule_event()
[1520449504.990521] [001.0] [pid=21572] add_event()
[1520449514.975362] [001.0] [pid=21572] handle_timed_event() start
[1520449514.975505] [001.0] [pid=21572] reap_check_results() start
[1520449514.975587] [001.0] [pid=21572] reap_check_results() end
[1520449514.975601] [001.0] [pid=21572] handle_timed_event() end
[1520449514.975609] [001.0] [pid=21572] reschedule_event()
[1520449514.975613] [001.0] [pid=21572] add_event()
[1520449514.975631] [001.0] [pid=21572] handle_timed_event() start
[1520449514.975677] [001.0] [pid=21572] save_status_data()
[1520449514.990926] [001.0] [pid=21572] handle_timed_event() end
[1520449514.990961] [001.0] [pid=21572] reschedule_event()
[1520449514.990970] [001.0] [pid=21572] add_event()
[1520449519.975439] [001.0] [pid=21572] handle_timed_event() start
[1520449519.975550] [001.0] [pid=21572] process_host_perfdata_file()
[1520449519.975559] [001.0] [pid=21572] get_raw_command_line_r()
[1520449519.975574] [001.0] [pid=21572] process_macros_r()
[1520449519.975656] [001.0] [pid=21572] my_system_r()
[1520449519.979916] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449519.980021] [001.0] [pid=21572] handle_timed_event() end
[1520449519.980039] [001.0] [pid=21572] reschedule_event()
[1520449519.980044] [001.0] [pid=21572] add_event()
[1520449519.980344] [001.0] [pid=21572] handle_timed_event() start
[1520449519.980363] [001.0] [pid=21572] process_service_perfdata_file()
[1520449519.980369] [001.0] [pid=21572] get_raw_command_line_r()
[1520449519.980377] [001.0] [pid=21572] process_macros_r()
[1520449519.980395] [001.0] [pid=21572] my_system_r()
[1520449519.983822] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449519.983839] [001.0] [pid=21572] handle_timed_event() end
[1520449519.983854] [001.0] [pid=21572] reschedule_event()
[1520449519.983859] [001.0] [pid=21572] add_event()
[1520449524.975127] [001.0] [pid=21572] handle_timed_event() start
[1520449524.975236] [001.0] [pid=21572] reap_check_results() start
[1520449524.975334] [001.0] [pid=21572] reap_check_results() end
[1520449524.975346] [001.0] [pid=21572] handle_timed_event() end
[1520449524.975352] [001.0] [pid=21572] reschedule_event()
[1520449524.975357] [001.0] [pid=21572] add_event()
[1520449524.975374] [001.0] [pid=21572] handle_timed_event() start
[1520449524.975405] [001.0] [pid=21572] save_status_data()
[1520449524.983787] [001.0] [pid=21572] handle_timed_event() end
[1520449524.983811] [001.0] [pid=21572] reschedule_event()
[1520449524.983819] [001.0] [pid=21572] add_event()
[1520449534.975361] [001.0] [pid=21572] handle_timed_event() start
[1520449534.975434] [001.0] [pid=21572] reap_check_results() start
[1520449534.975464] [001.0] [pid=21572] reap_check_results() end
[1520449534.975469] [001.0] [pid=21572] handle_timed_event() end
[1520449534.975475] [001.0] [pid=21572] reschedule_event()
[1520449534.975480] [001.0] [pid=21572] add_event()
[1520449534.975494] [001.0] [pid=21572] handle_timed_event() start
[1520449534.975524] [001.0] [pid=21572] save_status_data()
[1520449534.978051] [001.0] [pid=21572] handle_timed_event() end
[1520449534.978064] [001.0] [pid=21572] reschedule_event()
[1520449534.978078] [001.0] [pid=21572] add_event()
[1520449534.978095] [001.0] [pid=21572] handle_timed_event() start
[1520449534.978106] [001.0] [pid=21572] process_service_perfdata_file()
[1520449534.978112] [001.0] [pid=21572] get_raw_command_line_r()
[1520449534.978122] [001.0] [pid=21572] process_macros_r()
[1520449534.978142] [001.0] [pid=21572] my_system_r()
[1520449534.982049] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449534.982067] [001.0] [pid=21572] handle_timed_event() end
[1520449534.982081] [001.0] [pid=21572] reschedule_event()
[1520449534.982086] [001.0] [pid=21572] add_event()
[1520449534.982105] [001.0] [pid=21572] handle_timed_event() start
[1520449534.982115] [001.0] [pid=21572] check_for_orphaned_hosts()
[1520449534.982120] [001.0] [pid=21572] check_for_orphaned_services()
[1520449534.982124] [001.0] [pid=21572] handle_timed_event() end
[1520449534.982129] [001.0] [pid=21572] reschedule_event()
[1520449534.982133] [001.0] [pid=21572] add_event()
[1520449534.982144] [001.0] [pid=21572] handle_timed_event() start
[1520449534.982153] [001.0] [pid=21572] process_host_perfdata_file()
[1520449534.982158] [001.0] [pid=21572] get_raw_command_line_r()
[1520449534.982165] [001.0] [pid=21572] process_macros_r()
[1520449534.982182] [001.0] [pid=21572] my_system_r()
[1520449534.985476] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449534.985536] [001.0] [pid=21572] handle_timed_event() end
[1520449534.985552] [001.0] [pid=21572] reschedule_event()
[1520449534.985557] [001.0] [pid=21572] add_event()
[1520449534.985575] [001.0] [pid=21572] handle_timed_event() start
[1520449534.985586] [001.0] [pid=21572] adjust_check_scheduling() start
[1520449534.985593] [001.0] [pid=21572] handle_timed_event() end
[1520449534.985598] [001.0] [pid=21572] reschedule_event()
[1520449534.985602] [001.0] [pid=21572] add_event()
[1520449534.985612] [001.0] [pid=21572] handle_timed_event() start
[1520449534.985622] [001.0] [pid=21572] check_service_result_freshness()
[1520449534.985626] [001.0] [pid=21572] handle_timed_event() end
[1520449534.985636] [001.0] [pid=21572] reschedule_event()
[1520449534.985641] [001.0] [pid=21572] add_event()
[1520449544.975230] [001.0] [pid=21572] handle_timed_event() start
[1520449544.975380] [001.0] [pid=21572] reap_check_results() start
[1520449544.975433] [001.0] [pid=21572] reap_check_results() end
[1520449544.975441] [001.0] [pid=21572] handle_timed_event() end
[1520449544.975448] [001.0] [pid=21572] reschedule_event()
[1520449544.975452] [001.0] [pid=21572] add_event()
[1520449544.975468] [001.0] [pid=21572] handle_timed_event() start
[1520449544.975499] [001.0] [pid=21572] save_status_data()
[1520449544.978358] [001.0] [pid=21572] handle_timed_event() end
[1520449544.978374] [001.0] [pid=21572] reschedule_event()
[1520449544.978379] [001.0] [pid=21572] add_event()
[1520449549.974813] [001.0] [pid=21572] handle_timed_event() start
[1520449549.974950] [001.0] [pid=21572] process_service_perfdata_file()
[1520449549.974959] [001.0] [pid=21572] get_raw_command_line_r()
[1520449549.974974] [001.0] [pid=21572] process_macros_r()
[1520449549.975020] [001.0] [pid=21572] my_system_r()
[1520449549.979130] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449549.979149] [001.0] [pid=21572] handle_timed_event() end
[1520449549.979164] [001.0] [pid=21572] reschedule_event()
[1520449549.979169] [001.0] [pid=21572] add_event()
[1520449549.979191] [001.0] [pid=21572] handle_timed_event() start
[1520449549.979202] [001.0] [pid=21572] process_host_perfdata_file()
[1520449549.979207] [001.0] [pid=21572] get_raw_command_line_r()
[1520449549.979214] [001.0] [pid=21572] process_macros_r()
[1520449549.979230] [001.0] [pid=21572] my_system_r()
[1520449549.982634] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449549.982698] [001.0] [pid=21572] handle_timed_event() end
[1520449549.982715] [001.0] [pid=21572] reschedule_event()
[1520449549.982720] [001.0] [pid=21572] add_event()
[1520449554.974999] [001.0] [pid=21572] handle_timed_event() start
[1520449554.975113] [001.0] [pid=21572] reap_check_results() start
[1520449554.975167] [001.0] [pid=21572] reap_check_results() end
[1520449554.975181] [001.0] [pid=21572] handle_timed_event() end
[1520449554.975189] [001.0] [pid=21572] reschedule_event()
[1520449554.975193] [001.0] [pid=21572] add_event()
[1520449554.975209] [001.0] [pid=21572] handle_timed_event() start
[1520449554.975241] [001.0] [pid=21572] save_status_data()
[1520449554.983843] [001.0] [pid=21572] handle_timed_event() end
[1520449554.983863] [001.0] [pid=21572] reschedule_event()
[1520449554.983868] [001.0] [pid=21572] add_event()
[1520449564.975944] [001.0] [pid=21572] handle_timed_event() start
[1520449564.976072] [001.0] [pid=21572] reap_check_results() start
[1520449564.976168] [001.0] [pid=21572] reap_check_results() end
[1520449564.976183] [001.0] [pid=21572] handle_timed_event() end
[1520449564.976190] [001.0] [pid=21572] reschedule_event()
[1520449564.976195] [001.0] [pid=21572] add_event()
[1520449564.976212] [001.0] [pid=21572] handle_timed_event() start
[1520449564.976244] [001.0] [pid=21572] save_status_data()
[1520449564.978850] [001.0] [pid=21572] handle_timed_event() end
[1520449564.978870] [001.0] [pid=21572] reschedule_event()
[1520449564.978876] [001.0] [pid=21572] add_event()
[1520449564.978897] [001.0] [pid=21572] handle_timed_event() start
[1520449564.978908] [001.0] [pid=21572] process_host_perfdata_file()
[1520449564.978916] [001.0] [pid=21572] get_raw_command_line_r()
[1520449564.978931] [001.0] [pid=21572] process_macros_r()
[1520449564.978953] [001.0] [pid=21572] my_system_r()
[1520449564.983393] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449564.983479] [001.0] [pid=21572] handle_timed_event() end
[1520449564.983504] [001.0] [pid=21572] reschedule_event()
[1520449564.983511] [001.0] [pid=21572] add_event()
[1520449564.983538] [001.0] [pid=21572] handle_timed_event() start
[1520449564.983573] [001.0] [pid=21572] process_service_perfdata_file()
[1520449564.983756] [001.0] [pid=21572] get_raw_command_line_r()
[1520449564.983808] [001.0] [pid=21572] process_macros_r()
[1520449564.983852] [001.0] [pid=21572] my_system_r()
[1520449564.987863] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449564.987888] [001.0] [pid=21572] handle_timed_event() end
[1520449564.987903] [001.0] [pid=21572] reschedule_event()
[1520449564.987908] [001.0] [pid=21572] add_event()
[1520449564.987929] [001.0] [pid=21572] handle_timed_event() start
[1520449564.987940] [001.0] [pid=21572] adjust_check_scheduling() start
[1520449564.987949] [001.0] [pid=21572] handle_timed_event() end
[1520449564.987954] [001.0] [pid=21572] reschedule_event()
[1520449564.987958] [001.0] [pid=21572] add_event()
[1520449574.975453] [001.0] [pid=21572] handle_timed_event() start
[1520449574.975668] [001.0] [pid=21572] save_status_data()
[1520449574.977975] [001.0] [pid=21572] handle_timed_event() end
[1520449574.977996] [001.0] [pid=21572] reschedule_event()
[1520449574.978002] [001.0] [pid=21572] add_event()
[1520449574.978023] [001.0] [pid=21572] handle_timed_event() start
[1520449574.978034] [001.0] [pid=21572] reap_check_results() start
[1520449574.978084] [001.0] [pid=21572] reap_check_results() end
[1520449574.978095] [001.0] [pid=21572] handle_timed_event() end
[1520449574.978101] [001.0] [pid=21572] reschedule_event()
[1520449574.978105] [001.0] [pid=21572] add_event()
[1520449579.975359] [001.0] [pid=21572] handle_timed_event() start
[1520449579.975491] [001.0] [pid=21572] process_service_perfdata_file()
[1520449579.975529] [001.0] [pid=21572] get_raw_command_line_r()
[1520449579.975556] [001.0] [pid=21572] process_macros_r()
[1520449579.975590] [001.0] [pid=21572] my_system_r()
[1520449579.980218] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449579.980247] [001.0] [pid=21572] handle_timed_event() end
[1520449579.980261] [001.0] [pid=21572] reschedule_event()
[1520449579.980266] [001.0] [pid=21572] add_event()
[1520449579.980288] [001.0] [pid=21572] handle_timed_event() start
[1520449579.980328] [001.0] [pid=21572] process_host_perfdata_file()
[1520449579.980344] [001.0] [pid=21572] get_raw_command_line_r()
[1520449579.980356] [001.0] [pid=21572] process_macros_r()
[1520449579.980380] [001.0] [pid=21572] my_system_r()
[1520449579.983959] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449579.984034] [001.0] [pid=21572] handle_timed_event() end
[1520449579.984052] [001.0] [pid=21572] reschedule_event()
[1520449579.984057] [001.0] [pid=21572] add_event()
[1520449584.975507] [001.0] [pid=21572] handle_timed_event() start
[1520449584.975657] [001.0] [pid=21572] save_status_data()
[1520449584.977902] [001.0] [pid=21572] handle_timed_event() end
[1520449584.977919] [001.0] [pid=21572] reschedule_event()
[1520449584.977924] [001.0] [pid=21572] add_event()
[1520449584.977943] [001.0] [pid=21572] handle_timed_event() start
[1520449584.977954] [001.0] [pid=21572] reap_check_results() start
[1520449584.977984] [001.0] [pid=21572] reap_check_results() end
[1520449584.978006] [001.0] [pid=21572] handle_timed_event() end
[1520449584.978013] [001.0] [pid=21572] reschedule_event()
[1520449584.978017] [001.0] [pid=21572] add_event()
[1520449594.975356] [001.0] [pid=21572] handle_timed_event() start
[1520449594.975496] [001.0] [pid=21572] save_status_data()
[1520449594.979804] [001.0] [pid=21572] handle_timed_event() end
[1520449594.979821] [001.0] [pid=21572] reschedule_event()
[1520449594.979827] [001.0] [pid=21572] add_event()
[1520449594.979847] [001.0] [pid=21572] handle_timed_event() start
[1520449594.979857] [001.0] [pid=21572] reap_check_results() start
[1520449594.979882] [001.0] [pid=21572] reap_check_results() end
[1520449594.979906] [001.0] [pid=21572] handle_timed_event() end
[1520449594.979913] [001.0] [pid=21572] reschedule_event()
[1520449594.979918] [001.0] [pid=21572] add_event()
[1520449594.979935] [001.0] [pid=21572] handle_timed_event() start
[1520449594.979945] [001.0] [pid=21572] process_host_perfdata_file()
[1520449594.979952] [001.0] [pid=21572] get_raw_command_line_r()
[1520449594.979964] [001.0] [pid=21572] process_macros_r()
[1520449594.979983] [001.0] [pid=21572] my_system_r()
[1520449594.983974] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449594.984047] [001.0] [pid=21572] handle_timed_event() end
[1520449594.984071] [001.0] [pid=21572] reschedule_event()
[1520449594.984076] [001.0] [pid=21572] add_event()
[1520449594.984097] [001.0] [pid=21572] handle_timed_event() start
[1520449594.984112] [001.0] [pid=21572] check_service_result_freshness()
[1520449594.984117] [001.0] [pid=21572] handle_timed_event() end
[1520449594.984122] [001.0] [pid=21572] reschedule_event()
[1520449594.984126] [001.0] [pid=21572] add_event()
[1520449594.984150] [001.0] [pid=21572] handle_timed_event() start
[1520449594.984162] [001.0] [pid=21572] process_service_perfdata_file()
[1520449594.984168] [001.0] [pid=21572] get_raw_command_line_r()
[1520449594.984176] [001.0] [pid=21572] process_macros_r()
[1520449594.984193] [001.0] [pid=21572] my_system_r()
[1520449594.987546] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449594.987563] [001.0] [pid=21572] handle_timed_event() end
[1520449594.987577] [001.0] [pid=21572] reschedule_event()
[1520449594.987581] [001.0] [pid=21572] add_event()
[1520449594.987601] [001.0] [pid=21572] handle_timed_event() start
[1520449594.987612] [001.0] [pid=21572] adjust_check_scheduling() start
[1520449594.987619] [001.0] [pid=21572] handle_timed_event() end
[1520449594.987624] [001.0] [pid=21572] reschedule_event()
[1520449594.987854] [001.0] [pid=21572] add_event()
[1520449594.987876] [001.0] [pid=21572] handle_timed_event() start
[1520449594.987893] [001.0] [pid=21572] check_for_orphaned_hosts()
[1520449594.987899] [001.0] [pid=21572] check_for_orphaned_services()
[1520449594.987904] [001.0] [pid=21572] handle_timed_event() end
[1520449594.987910] [001.0] [pid=21572] reschedule_event()
[1520449594.987915] [001.0] [pid=21572] add_event()
[1520449604.975374] [001.0] [pid=21572] handle_timed_event() start
[1520449604.975496] [001.0] [pid=21572] save_status_data()
[1520449604.977429] [001.0] [pid=21572] handle_timed_event() end
[1520449604.977444] [001.0] [pid=21572] reschedule_event()
[1520449604.977450] [001.0] [pid=21572] add_event()
[1520449604.977469] [001.0] [pid=21572] handle_timed_event() start
[1520449604.977488] [001.0] [pid=21572] reap_check_results() start
[1520449604.977516] [001.0] [pid=21572] reap_check_results() end
[1520449604.977523] [001.0] [pid=21572] handle_timed_event() end
[1520449604.977528] [001.0] [pid=21572] reschedule_event()
[1520449604.977533] [001.0] [pid=21572] add_event()
[1520449609.974858] [001.0] [pid=21572] handle_timed_event() start
[1520449609.974973] [001.0] [pid=21572] process_host_perfdata_file()
[1520449609.974981] [001.0] [pid=21572] get_raw_command_line_r()
[1520449609.974996] [001.0] [pid=21572] process_macros_r()
[1520449609.975033] [001.0] [pid=21572] my_system_r()
[1520449609.979963] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449609.980076] [001.0] [pid=21572] handle_timed_event() end
[1520449609.980105] [001.0] [pid=21572] reschedule_event()
[1520449609.980114] [001.0] [pid=21572] add_event()
[1520449609.980145] [001.0] [pid=21572] handle_timed_event() start
[1520449609.980163] [001.0] [pid=21572] process_service_perfdata_file()
[1520449609.980172] [001.0] [pid=21572] get_raw_command_line_r()
[1520449609.980183] [001.0] [pid=21572] process_macros_r()
[1520449609.980211] [001.0] [pid=21572] my_system_r()
[1520449609.984482] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449609.984513] [001.0] [pid=21572] handle_timed_event() end
[1520449609.984536] [001.0] [pid=21572] reschedule_event()
[1520449609.984544] [001.0] [pid=21572] add_event()
[1520449614.974763] [001.0] [pid=21572] handle_timed_event() start
[1520449614.974939] [001.0] [pid=21572] save_status_data()
[1520449614.977172] [001.0] [pid=21572] handle_timed_event() end
[1520449614.977194] [001.0] [pid=21572] reschedule_event()
[1520449614.977200] [001.0] [pid=21572] add_event()
[1520449614.977221] [001.0] [pid=21572] handle_timed_event() start
[1520449614.977232] [001.0] [pid=21572] reap_check_results() start
[1520449614.977263] [001.0] [pid=21572] reap_check_results() end
[1520449614.977272] [001.0] [pid=21572] handle_timed_event() end
[1520449614.977283] [001.0] [pid=21572] reschedule_event()
[1520449614.977288] [001.0] [pid=21572] add_event()
[1520449624.975964] [001.0] [pid=21572] handle_timed_event() start
[1520449624.976108] [001.0] [pid=21572] save_status_data()
[1520449624.978084] [001.0] [pid=21572] handle_timed_event() end
[1520449624.978105] [001.0] [pid=21572] reschedule_event()
[1520449624.978111] [001.0] [pid=21572] add_event()
[1520449624.978132] [001.0] [pid=21572] handle_timed_event() start
[1520449624.978143] [001.0] [pid=21572] reap_check_results() start
[1520449624.978168] [001.0] [pid=21572] reap_check_results() end
[1520449624.978177] [001.0] [pid=21572] handle_timed_event() end
[1520449624.978182] [001.0] [pid=21572] reschedule_event()
[1520449624.978186] [001.0] [pid=21572] add_event()
[1520449624.978198] [001.0] [pid=21572] handle_timed_event() start
[1520449624.978208] [001.0] [pid=21572] process_service_perfdata_file()
[1520449624.978225] [001.0] [pid=21572] get_raw_command_line_r()
[1520449624.978235] [001.0] [pid=21572] process_macros_r()
[1520449624.978256] [001.0] [pid=21572] my_system_r()
[1520449624.982327] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449624.982352] [001.0] [pid=21572] handle_timed_event() end
[1520449624.982366] [001.0] [pid=21572] reschedule_event()
[1520449624.982371] [001.0] [pid=21572] add_event()
[1520449624.982391] [001.0] [pid=21572] handle_timed_event() start
[1520449624.982401] [001.0] [pid=21572] process_host_perfdata_file()
[1520449624.982406] [001.0] [pid=21572] get_raw_command_line_r()
[1520449624.982413] [001.0] [pid=21572] process_macros_r()
[1520449624.982432] [001.0] [pid=21572] my_system_r()
[1520449624.985888] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449624.985945] [001.0] [pid=21572] handle_timed_event() end
[1520449624.985961] [001.0] [pid=21572] reschedule_event()
[1520449624.985966] [001.0] [pid=21572] add_event()
[1520449624.985985] [001.0] [pid=21572] handle_timed_event() start
[1520449624.985995] [001.0] [pid=21572] adjust_check_scheduling() start
[1520449624.986004] [001.0] [pid=21572] handle_timed_event() end
[1520449624.986008] [001.0] [pid=21572] reschedule_event()
[1520449624.986013] [001.0] [pid=21572] add_event()
[1520449626.260757] [001.0] [pid=21572] handle_async_service_check_result()
[1520449626.260782] [001.0] [pid=21572] get_service_check_return_code()
[1520449626.260812] [001.0] [pid=21572] schedule_host_check()
[1520449626.260841] [001.0] [pid=21572] add_event()
[1520449626.260874] [001.0] [pid=21572] check_for_service_flapping()
[1520449626.260881] [001.0] [pid=21572] check_for_host_flapping()
[1520449626.260888] [001.0] [pid=21572] service_notification()
[1520449626.260904] [001.0] [pid=21572] check_service_notification_viability()
[1520449626.260909] [001.0] [pid=21572] check_time_against_period()
[1520449626.260918] [001.0] [pid=21572] _get_matching_timerange()
[1520449626.260932] [001.0] [pid=21572] get_next_valid_time()
[1520449626.260940] [001.0] [pid=21572] _get_matching_timerange()
[1520449626.260948] [001.0] [pid=21572] schedule_service_check()
[1520449626.260958] [001.0] [pid=21572] add_event()
[1520449626.261006] [001.0] [pid=21572] run_service_performance_data_command()
[1520449626.261012] [001.0] [pid=21572] update_service_performance_data_file()
[1520449626.261018] [001.0] [pid=21572] process_macros_r()
[1520449626.261080] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449626.261127] [001.0] [pid=21572] handle_timed_event() start
[1520449626.261141] [001.0] [pid=21572] run_scheduled_host_check()
[1520449626.261146] [001.0] [pid=21572] run_async_host_check([HOST FQDN] ...)
[1520449626.261151] [001.0] [pid=21572] check_host_check_viability()
[1520449626.261155] [001.0] [pid=21572] check_time_against_period()
[1520449626.261164] [001.0] [pid=21572] _get_matching_timerange()
[1520449626.261172] [001.0] [pid=21572] check_host_dependencies()
[1520449626.261178] [001.0] [pid=21572] adjust_host_check_attempt()
[1520449626.261184] [001.0] [pid=21572] get_raw_command_line_r()
[1520449626.261197] [001.0] [pid=21572] process_macros_r()
[1520449626.261203] [001.0] [pid=21572] process_macros_r()
[1520449626.261208] [001.0] [pid=21572] process_macros_r()
[1520449626.261214] [001.0] [pid=21572] process_macros_r()
[1520449626.261218] [001.0] [pid=21572] process_macros_r()
[1520449626.261223] [001.0] [pid=21572] process_macros_r()
[1520449626.261227] [001.0] [pid=21572] process_macros_r()
[1520449626.261233] [001.0] [pid=21572] process_macros_r()
[1520449626.261238] [001.0] [pid=21572] process_macros_r()
[1520449626.261257] [001.0] [pid=21572] macros_to_kvv()
[1520449626.261277] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449626.261284] [001.0] [pid=21572] handle_timed_event() end
[1520449626.445296] [001.0] [pid=21572] handle_async_host_check_result([HOST FQDN] ...)
[1520449626.445377] [001.0] [pid=21572] get_host_check_return_code()
[1520449626.445411] [001.0] [pid=21572] process_host_check_result()
[1520449626.445419] [001.0] [pid=21572] handle_host_state()
[1520449626.445431] [001.0] [pid=21572] obsessive_compulsive_host_check_processor()
[1520449626.445588] [001.0] [pid=21572] run_host_performance_data_command()
[1520449626.445596] [001.0] [pid=21572] update_host_performance_data_file()
[1520449626.445608] [001.0] [pid=21572] process_macros_r()
[1520449626.445667] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449626.445677] [001.0] [pid=21572] check_for_host_flapping()
[1520449626.445708] [001.0] [pid=21572] get_next_valid_time()
[1520449626.445719] [001.0] [pid=21572] _get_matching_timerange()
[1520449626.445729] [001.0] [pid=21572] schedule_host_check()
[1520449626.445739] [001.0] [pid=21572] add_event()
[1520449634.975339] [001.0] [pid=21572] handle_timed_event() start
[1520449634.975476] [001.0] [pid=21572] reap_check_results() start
[1520449634.975536] [001.0] [pid=21572] reap_check_results() end
[1520449634.975545] [001.0] [pid=21572] handle_timed_event() end
[1520449634.975551] [001.0] [pid=21572] reschedule_event()
[1520449634.975556] [001.0] [pid=21572] add_event()
[1520449634.975572] [001.0] [pid=21572] handle_timed_event() start
[1520449634.975604] [001.0] [pid=21572] save_status_data()
[1520449634.978269] [001.0] [pid=21572] handle_timed_event() end
[1520449634.978284] [001.0] [pid=21572] reschedule_event()
[1520449634.978289] [001.0] [pid=21572] add_event()
[1520449639.974584] [001.0] [pid=21572] handle_timed_event() start
[1520449639.974670] [001.0] [pid=21572] process_host_perfdata_file()
[1520449639.974678] [001.0] [pid=21572] get_raw_command_line_r()
[1520449639.974686] [001.0] [pid=21572] process_macros_r()
[1520449639.974778] [001.0] [pid=21572] my_system_r()
[1520449639.978978] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449639.979059] [001.0] [pid=21572] handle_timed_event() end
[1520449639.979080] [001.0] [pid=21572] reschedule_event()
[1520449639.979085] [001.0] [pid=21572] add_event()
[1520449639.979108] [001.0] [pid=21572] handle_timed_event() start
[1520449639.979118] [001.0] [pid=21572] process_service_perfdata_file()
[1520449639.979124] [001.0] [pid=21572] get_raw_command_line_r()
[1520449639.979131] [001.0] [pid=21572] process_macros_r()
[1520449639.979160] [001.0] [pid=21572] my_system_r()
[1520449639.982829] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449639.982854] [001.0] [pid=21572] handle_timed_event() end
[1520449639.982867] [001.0] [pid=21572] reschedule_event()
[1520449639.982886] [001.0] [pid=21572] add_event()
[1520449644.975264] [001.0] [pid=21572] handle_timed_event() start
[1520449644.975448] [001.0] [pid=21572] save_status_data()
[1520449644.977412] [001.0] [pid=21572] handle_timed_event() end
[1520449644.977441] [001.0] [pid=21572] reschedule_event()
[1520449644.977450] [001.0] [pid=21572] add_event()
[1520449644.977480] [001.0] [pid=21572] handle_timed_event() start
[1520449644.977506] [001.0] [pid=21572] reap_check_results() start
[1520449644.977549] [001.0] [pid=21572] reap_check_results() end
[1520449644.977568] [001.0] [pid=21572] handle_timed_event() end
[1520449644.977577] [001.0] [pid=21572] reschedule_event()
[1520449644.977601] [001.0] [pid=21572] add_event()
[1520449654.975512] [001.0] [pid=21572] handle_timed_event() start
[1520449654.975669] [001.0] [pid=21572] save_status_data()
[1520449654.977785] [001.0] [pid=21572] handle_timed_event() end
[1520449654.977807] [001.0] [pid=21572] reschedule_event()
[1520449654.977813] [001.0] [pid=21572] add_event()
[1520449654.977835] [001.0] [pid=21572] handle_timed_event() start
[1520449654.977865] [001.0] [pid=21572] reap_check_results() start
[1520449654.977895] [001.0] [pid=21572] reap_check_results() end
[1520449654.977901] [001.0] [pid=21572] handle_timed_event() end
[1520449654.977910] [001.0] [pid=21572] reschedule_event()
[1520449654.977915] [001.0] [pid=21572] add_event()
[1520449654.977927] [001.0] [pid=21572] handle_timed_event() start
[1520449654.977941] [001.0] [pid=21572] check_for_orphaned_hosts()
[1520449654.977946] [001.0] [pid=21572] check_for_orphaned_services()
[1520449654.977951] [001.0] [pid=21572] handle_timed_event() end
[1520449654.977971] [001.0] [pid=21572] reschedule_event()
[1520449654.977977] [001.0] [pid=21572] add_event()
[1520449654.977990] [001.0] [pid=21572] handle_timed_event() start
[1520449654.978007] [001.0] [pid=21572] adjust_check_scheduling() start
[1520449654.978017] [001.0] [pid=21572] handle_timed_event() end
[1520449654.978022] [001.0] [pid=21572] reschedule_event()
[1520449654.978027] [001.0] [pid=21572] add_event()
[1520449654.978037] [001.0] [pid=21572] handle_timed_event() start
[1520449654.978050] [001.0] [pid=21572] process_service_perfdata_file()
[1520449654.978058] [001.0] [pid=21572] get_raw_command_line_r()
[1520449654.978068] [001.0] [pid=21572] process_macros_r()
[1520449654.978087] [001.0] [pid=21572] my_system_r()
[1520449654.982023] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449654.982048] [001.0] [pid=21572] handle_timed_event() end
[1520449654.982063] [001.0] [pid=21572] reschedule_event()
[1520449654.982068] [001.0] [pid=21572] add_event()
[1520449654.982091] [001.0] [pid=21572] handle_timed_event() start
[1520449654.982109] [001.0] [pid=21572] process_host_perfdata_file()
[1520449654.982115] [001.0] [pid=21572] get_raw_command_line_r()
[1520449654.982123] [001.0] [pid=21572] process_macros_r()
[1520449654.982142] [001.0] [pid=21572] my_system_r()
[1520449654.985440] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449654.985505] [001.0] [pid=21572] handle_timed_event() end
[1520449654.985529] [001.0] [pid=21572] reschedule_event()
[1520449654.985534] [001.0] [pid=21572] add_event()
[1520449654.985554] [001.0] [pid=21572] handle_timed_event() start
[1520449654.985568] [001.0] [pid=21572] check_service_result_freshness()
[1520449654.985574] [001.0] [pid=21572] handle_timed_event() end
[1520449654.985580] [001.0] [pid=21572] reschedule_event()
[1520449654.985585] [001.0] [pid=21572] add_event()
[1520449664.975362] [001.0] [pid=21572] handle_timed_event() start
[1520449664.975500] [001.0] [pid=21572] reap_check_results() start
[1520449664.975553] [001.0] [pid=21572] reap_check_results() end
[1520449664.975561] [001.0] [pid=21572] handle_timed_event() end
[1520449664.975569] [001.0] [pid=21572] reschedule_event()
[1520449664.975573] [001.0] [pid=21572] add_event()
[1520449664.975588] [001.0] [pid=21572] handle_timed_event() start
[1520449664.975628] [001.0] [pid=21572] save_status_data()
[1520449664.977735] [001.0] [pid=21572] handle_timed_event() end
[1520449664.977752] [001.0] [pid=21572] reschedule_event()
[1520449664.977757] [001.0] [pid=21572] add_event()
[1520449669.975086] [001.0] [pid=21572] handle_timed_event() start
[1520449669.975201] [001.0] [pid=21572] process_service_perfdata_file()
[1520449669.975211] [001.0] [pid=21572] get_raw_command_line_r()
[1520449669.975228] [001.0] [pid=21572] process_macros_r()
[1520449669.975266] [001.0] [pid=21572] my_system_r()
[1520449669.980022] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449669.980055] [001.0] [pid=21572] handle_timed_event() end
[1520449669.980075] [001.0] [pid=21572] reschedule_event()
[1520449669.980083] [001.0] [pid=21572] add_event()
[1520449669.980134] [001.0] [pid=21572] handle_timed_event() start
[1520449669.980158] [001.0] [pid=21572] process_host_perfdata_file()
[1520449669.980175] [001.0] [pid=21572] get_raw_command_line_r()
[1520449669.980189] [001.0] [pid=21572] process_macros_r()
[1520449669.980226] [001.0] [pid=21572] my_system_r()
[1520449669.984209] [001.0] [pid=21572] clear_volatile_macros_r()
[1520449669.984298] [001.0] [pid=21572] handle_timed_event() end
[1520449669.984359] [001.0] [pid=21572] reschedule_event()
[1520449669.984388] [001.0] [pid=21572] add_event()
[1520449674.974683] [001.0] [pid=21572] handle_timed_event() start
[1520449674.974843] [001.0] [pid=21572] save_status_data()
[1520449674.976955] [001.0] [pid=21572] handle_timed_event() end
[1520449674.976971] [001.0] [pid=21572] reschedule_event()
[1520449674.976976] [001.0] [pid=21572] add_event()
[1520449674.976998] [001.0] [pid=21572] handle_timed_event() start
[1520449674.977009] [001.0] [pid=21572] reap_check_results() start
[1520449674.977039] [001.0] [pid=21572] reap_check_results() end
[1520449674.977046] [001.0] [pid=21572] handle_timed_event() end
[1520449674.977051] [001.0] [pid=21572] reschedule_event()
[1520449674.977055] [001.0] [pid=21572] add_event()

[tgriep]

The debug level needs to be a minus 1 "-1" and not 1 so can you change it again and see if you can capture anything in the debug log?

[benjohns]

This looks more useful:

$ tail -f /usr/local/nagios/var/nagios.debug

Code: Select all

[1520622376.986228] [001.0] [pid=23633] add_event()
[1520622376.986232] [008.1] [pid=23633] ** Event Check Loop
[1520622376.986241] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:27 2018
[1520622376.986245] [008.1] [pid=23633] Current/Max Service Checks: 1/0 (inf% saturation)
[1520622376.986249] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622378.487805] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622379.989384] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622381.490340] [064.1] [pid=23633] Making callbacks (type 11)...
[1520622381.490433] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622382.991339] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622384.492924] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622385.994371] [12288.1] [pid=23633] ## Polling 980ms; sockets=8; events=11; iobs=0x1f6c140
[1520622386.288991] [256.1] [pid=23633] Read raw external command '[1520622386] SCHEDULE_FORCED_SVC_CHECK;[HOST];CPU Usage for VMHost;1520622375'
[1520622386.289018] [001.0] [pid=23633] process_external_command1()
[1520622386.289039] [064.1] [pid=23633] Making callbacks (type 17)...
[1520622386.289064] [001.0] [pid=23633] process_external_command2()
[1520622386.289069] [128.1] [pid=23633] External Command Type: 54
[1520622386.289073] [128.1] [pid=23633] Command Entry Time: 1520622386
[1520622386.289077] [128.1] [pid=23633] Command Arguments: [HOST];CPU Usage for VMHost;1520622375
[1520622386.289085] [001.0] [pid=23633] schedule_service_check()
[1520622386.289105] [016.0] [pid=23633] Scheduling a forced, active check of service 'CPU Usage for VMHost' on host '[HOST]' @ Fri Mar  9 13:06:15 2018
[1520622386.289112] [001.0] [pid=23633] add_event()
[1520622386.289118] [064.1] [pid=23633] Making callbacks (type 13)...
[1520622386.289156] [064.1] [pid=23633] Making callbacks (type 17)...
[1520622386.289170] [008.1] [pid=23633] ** Event Check Loop
[1520622386.289181] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:15 2018
[1520622386.289185] [008.1] [pid=23633] Current/Max Service Checks: 1/0 (inf% saturation)
[1520622386.289191] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=12; iobs=0x1f6c140
[1520622386.289198] [001.0] [pid=23633] handle_timed_event() start
[1520622386.289212] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622386.289222] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_SERVICE_CHECK, Run Time: Fri Mar  9 13:06:15 2018
[1520622386.289227] [008.0] [pid=23633] ** Service Check Event ==> Host: '[HOST]', Service: 'CPU Usage for VMHost', Options: 1, Latency: 0.000111 sec
[1520622386.289234] [001.0] [pid=23633] run_scheduled_service_check() start
[1520622386.289238] [016.0] [pid=23633] Attempting to run scheduled check of service 'CPU Usage for VMHost' on host '[HOST]': check options=1, latency=0.000111
[1520622386.289243] [001.0] [pid=23633] run_async_service_check()
[1520622386.289248] [001.0] [pid=23633] check_service_check_viability()
[1520622386.289253] [064.1] [pid=23633] Making callbacks (type 6)...
[1520622386.289257] [016.0] [pid=23633] Checking service 'CPU Usage for VMHost' on host '[HOST]'...
[1520622386.289265] [001.0] [pid=23633] get_raw_command_line_r()
[1520622386.289282] [001.0] [pid=23633] process_macros_r()
[1520622386.289312] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622386.289321] [2048.1] [pid=23633] Processing: '/usr/local/nagiosxi/etc/components/vmware/[HOST]_auth.txt'
[1520622386.289327] [2048.1] [pid=23633]   Done.  Final output: '/usr/local/nagiosxi/etc/components/vmware/[HOST]_auth.txt'
[1520622386.289397] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622386.289403] [001.0] [pid=23633] process_macros_r()
[1520622386.289407] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622386.289412] [2048.1] [pid=23633] Processing: 'CPU'
[1520622386.289417] [2048.1] [pid=23633]   Done.  Final output: 'CPU'
[1520622386.289422] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622386.289426] [001.0] [pid=23633] process_macros_r()
[1520622386.289430] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622386.289434] [2048.1] [pid=23633] Processing: ''
[1520622386.289441] [2048.1] [pid=23633]   Done.  Final output: ''
[1520622386.289446] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622386.289651] [001.0] [pid=23633] process_macros_r()
[1520622386.291723] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622386.291807] [2048.1] [pid=23633] Processing: '$USER1$/check_esx3.pl -H "$HOSTADDRESS$" -f "$ARG1$" -l "$ARG2$" $ARG3$'
[1520622386.291892] [2048.1] [pid=23633]   Done.  Final output: '/usr/local/nagios/libexec/check_esx3.pl -H "[IP]" -f "/usr/local/nagiosxi/etc/components/vmware/[HOST]_auth.txt" -l "CPU" '
[1520622386.291973] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622386.292067] [064.1] [pid=23633] Making callbacks (type 6)...
[1520622386.292177] [001.0] [pid=23633] macros_to_kvv()
[1520622386.292268] [001.0] [pid=23633] clear_volatile_macros_r()
[1520622386.292370] [001.0] [pid=23633] handle_timed_event() end
[1520622386.292396] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622386.292416] [008.1] [pid=23633] ** Event Check Loop
[1520622386.292508] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:27 2018
[1520622386.292531] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622386.292550] [12288.1] [pid=23633] ## Polling 682ms; sockets=8; events=11; iobs=0x1f6c140
[1520622386.975289] [001.0] [pid=23633] handle_timed_event() start
[1520622386.975339] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622386.975367] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_CHECK_REAPER, Run Time: Fri Mar  9 13:06:27 2018
[1520622386.975373] [008.0] [pid=23633] ** Check Result Reaper. Latency: 0.000s
[1520622386.975382] [001.0] [pid=23633] reap_check_results() start
[1520622386.975387] [016.0] [pid=23633] Starting to reap check results.
[1520622386.975414] [016.1] [pid=23633] Starting to read check result queue '/usr/local/nagios/var/spool/checkresults'...
[1520622386.975431] [016.0] [pid=23633] Finished reaping 0 check results
[1520622386.975445] [001.0] [pid=23633] reap_check_results() end
[1520622386.975449] [001.0] [pid=23633] handle_timed_event() end
[1520622386.975453] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622386.975459] [001.0] [pid=23633] reschedule_event()
[1520622386.975464] [001.0] [pid=23633] add_event()
[1520622386.975469] [008.1] [pid=23633] ** Event Check Loop
[1520622386.975480] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:27 2018
[1520622386.975484] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622386.975490] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622386.975497] [001.0] [pid=23633] handle_timed_event() start
[1520622386.975501] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622386.975510] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_STATUS_SAVE, Run Time: Fri Mar  9 13:06:27 2018
[1520622386.975514] [008.0] [pid=23633] ** Status Data Save Event. Latency: 0.000s
[1520622386.975520] [064.1] [pid=23633] Making callbacks (type 18)...
[1520622386.975539] [001.0] [pid=23633] save_status_data()
[1520622386.980882] [064.1] [pid=23633] Making callbacks (type 18)...
[1520622386.980915] [001.0] [pid=23633] handle_timed_event() end
[1520622386.980922] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622386.980927] [001.0] [pid=23633] reschedule_event()
[1520622386.980931] [001.0] [pid=23633] add_event()
[1520622386.980936] [008.1] [pid=23633] ** Event Check Loop
[1520622386.980951] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:32 2018
[1520622386.980956] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622386.980962] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622388.482512] [064.1] [pid=23633] Making callbacks (type 11)...
[1520622388.482610] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622389.984162] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622391.484340] [12288.1] [pid=23633] ## Polling 490ms; sockets=8; events=11; iobs=0x1f6c140
[1520622391.974964] [001.0] [pid=23633] handle_timed_event() start
[1520622391.975024] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622391.975087] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_USER_FUNCTION, Run Time: Fri Mar  9 13:06:32 2018
[1520622391.975094] [008.0] [pid=23633] ** User Function Event. Latency: 0.000s
[1520622391.975103] [001.0] [pid=23633] process_host_perfdata_file()
[1520622391.975110] [001.0] [pid=23633] get_raw_command_line_r()
[1520622391.975118] [001.0] [pid=23633] process_macros_r()
[1520622391.975123] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622391.975128] [2048.1] [pid=23633] Processing: '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/$TIMET$.perfdata.host'
[1520622391.975142] [2048.1] [pid=23633]   Done.  Final output: '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/1520622391.perfdata.host'
[1520622391.975146] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622391.975168] [001.0] [pid=23633] my_system_r()
[1520622391.975174] [256.1] [pid=23633] Running command '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/1520622391.perfdata.host'...
[1520622391.975191] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622391.979324] [256.1] [pid=23633] Execution time=0.004 sec, early timeout=0, result=0, output=(null)
[1520622391.979354] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622391.979386] [001.0] [pid=23633] clear_volatile_macros_r()
[1520622391.979461] [001.0] [pid=23633] handle_timed_event() end
[1520622391.979471] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622391.979482] [001.0] [pid=23633] reschedule_event()
[1520622391.979487] [001.0] [pid=23633] add_event()
[1520622391.979493] [008.1] [pid=23633] ** Event Check Loop
[1520622391.979510] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:32 2018
[1520622391.979516] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622391.979521] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622391.979529] [001.0] [pid=23633] handle_timed_event() start
[1520622391.979535] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622391.979544] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_USER_FUNCTION, Run Time: Fri Mar  9 13:06:32 2018
[1520622391.979552] [008.0] [pid=23633] ** User Function Event. Latency: 0.000s
[1520622391.979683] [001.0] [pid=23633] process_service_perfdata_file()
[1520622391.979901] [001.0] [pid=23633] get_raw_command_line_r()
[1520622391.980016] [001.0] [pid=23633] process_macros_r()
[1520622391.980029] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622391.980033] [2048.1] [pid=23633] Processing: '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/$TIMET$.perfdata.service'
[1520622391.980044] [2048.1] [pid=23633]   Done.  Final output: '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/1520622391.perfdata.service'
[1520622391.980061] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622391.980136] [001.0] [pid=23633] my_system_r()
[1520622391.980144] [256.1] [pid=23633] Running command '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/1520622391.perfdata.service'...
[1520622391.980157] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622391.983633] [256.1] [pid=23633] Execution time=0.003 sec, early timeout=0, result=0, output=(null)
[1520622391.983661] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622391.983765] [001.0] [pid=23633] clear_volatile_macros_r()
[1520622391.983780] [001.0] [pid=23633] handle_timed_event() end
[1520622391.983785] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622391.983795] [001.0] [pid=23633] reschedule_event()
[1520622391.983799] [001.0] [pid=23633] add_event()
[1520622391.983804] [008.1] [pid=23633] ** Event Check Loop
[1520622391.983824] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:37 2018
[1520622391.983845] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622391.983855] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622393.485416] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622394.987033] [064.1] [pid=23633] Making callbacks (type 11)...
[1520622394.987141] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622396.488705] [12288.1] [pid=23633] ## Polling 486ms; sockets=8; events=11; iobs=0x1f6c140
[1520622396.975284] [001.0] [pid=23633] handle_timed_event() start
[1520622396.975365] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622396.975417] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_CHECK_REAPER, Run Time: Fri Mar  9 13:06:37 2018
[1520622396.975423] [008.0] [pid=23633] ** Check Result Reaper. Latency: 0.000s
[1520622396.975468] [001.0] [pid=23633] reap_check_results() start
[1520622396.975475] [016.0] [pid=23633] Starting to reap check results.
[1520622396.975506] [016.1] [pid=23633] Starting to read check result queue '/usr/local/nagios/var/spool/checkresults'...
[1520622396.975533] [016.0] [pid=23633] Finished reaping 0 check results
[1520622396.975538] [001.0] [pid=23633] reap_check_results() end
[1520622396.975543] [001.0] [pid=23633] handle_timed_event() end
[1520622396.975547] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622396.975558] [001.0] [pid=23633] reschedule_event()
[1520622396.975562] [001.0] [pid=23633] add_event()
[1520622396.975568] [008.1] [pid=23633] ** Event Check Loop
[1520622396.975581] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:37 2018
[1520622396.975589] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622396.975598] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622396.975610] [001.0] [pid=23633] handle_timed_event() start
[1520622396.975619] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622396.975629] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_STATUS_SAVE, Run Time: Fri Mar  9 13:06:37 2018
[1520622396.975634] [008.0] [pid=23633] ** Status Data Save Event. Latency: 0.000s
[1520622396.975640] [064.1] [pid=23633] Making callbacks (type 18)...
[1520622396.975669] [001.0] [pid=23633] save_status_data()
[1520622396.980448] [064.1] [pid=23633] Making callbacks (type 18)...
[1520622396.980489] [001.0] [pid=23633] handle_timed_event() end
[1520622396.980496] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622396.980507] [001.0] [pid=23633] reschedule_event()
[1520622396.980628] [001.0] [pid=23633] add_event()
[1520622396.980635] [008.1] [pid=23633] ** Event Check Loop
[1520622396.980662] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:47 2018
[1520622396.980671] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622396.980677] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622398.482230] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622399.983820] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622401.485447] [064.1] [pid=23633] Making callbacks (type 11)...
[1520622401.485537] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622402.987097] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622404.488703] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622405.990289] [12288.1] [pid=23633] ## Polling 984ms; sockets=8; events=11; iobs=0x1f6c140
[1520622406.975354] [001.0] [pid=23633] handle_timed_event() start
[1520622406.975409] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.975449] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_CHECK_REAPER, Run Time: Fri Mar  9 13:06:47 2018
[1520622406.975455] [008.0] [pid=23633] ** Check Result Reaper. Latency: 0.000s
[1520622406.975465] [001.0] [pid=23633] reap_check_results() start
[1520622406.975469] [016.0] [pid=23633] Starting to reap check results.
[1520622406.975492] [016.1] [pid=23633] Starting to read check result queue '/usr/local/nagios/var/spool/checkresults'...
[1520622406.975516] [016.0] [pid=23633] Finished reaping 0 check results
[1520622406.975521] [001.0] [pid=23633] reap_check_results() end
[1520622406.975529] [001.0] [pid=23633] handle_timed_event() end
[1520622406.975534] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.975540] [001.0] [pid=23633] reschedule_event()
[1520622406.975545] [001.0] [pid=23633] add_event()
[1520622406.975554] [008.1] [pid=23633] ** Event Check Loop
[1520622406.975565] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:47 2018
[1520622406.975572] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622406.975578] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622406.975585] [001.0] [pid=23633] handle_timed_event() start
[1520622406.975589] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.975598] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_STATUS_SAVE, Run Time: Fri Mar  9 13:06:47 2018
[1520622406.975603] [008.0] [pid=23633] ** Status Data Save Event. Latency: 0.000s
[1520622406.975609] [064.1] [pid=23633] Making callbacks (type 18)...
[1520622406.975645] [001.0] [pid=23633] save_status_data()
[1520622406.977980] [064.1] [pid=23633] Making callbacks (type 18)...
[1520622406.978027] [001.0] [pid=23633] handle_timed_event() end
[1520622406.978035] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.978046] [001.0] [pid=23633] reschedule_event()
[1520622406.978051] [001.0] [pid=23633] add_event()
[1520622406.978057] [008.1] [pid=23633] ** Event Check Loop
[1520622406.978077] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:47 2018
[1520622406.978083] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622406.978089] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622406.978097] [001.0] [pid=23633] handle_timed_event() start
[1520622406.978102] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.978115] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_USER_FUNCTION, Run Time: Fri Mar  9 13:06:47 2018
[1520622406.978121] [008.0] [pid=23633] ** User Function Event. Latency: 0.000s
[1520622406.978128] [001.0] [pid=23633] process_service_perfdata_file()
[1520622406.978137] [001.0] [pid=23633] get_raw_command_line_r()
[1520622406.978146] [001.0] [pid=23633] process_macros_r()
[1520622406.978155] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622406.978160] [2048.1] [pid=23633] Processing: '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/$TIMET$.perfdata.service'
[1520622406.978177] [2048.1] [pid=23633]   Done.  Final output: '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/1520622406.perfdata.service'
[1520622406.978182] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622406.978193] [001.0] [pid=23633] my_system_r()
[1520622406.978198] [256.1] [pid=23633] Running command '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/1520622406.perfdata.service'...
[1520622406.978222] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622406.982402] [256.1] [pid=23633] Execution time=0.004 sec, early timeout=0, result=0, output=(null)
[1520622406.982433] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622406.982524] [001.0] [pid=23633] clear_volatile_macros_r()
[1520622406.982540] [001.0] [pid=23633] handle_timed_event() end
[1520622406.982546] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.982557] [001.0] [pid=23633] reschedule_event()
[1520622406.982563] [001.0] [pid=23633] add_event()
[1520622406.982569] [008.1] [pid=23633] ** Event Check Loop
[1520622406.982599] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:47 2018
[1520622406.982606] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622406.982612] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622406.982620] [001.0] [pid=23633] handle_timed_event() start
[1520622406.982626] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.982638] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_ORPHAN_CHECK, Run Time: Fri Mar  9 13:06:47 2018
[1520622406.982648] [008.0] [pid=23633] ** Orphaned Host and Service Check Event. Latency: 0.000s
[1520622406.982655] [001.0] [pid=23633] check_for_orphaned_hosts()
[1520622406.982661] [001.0] [pid=23633] check_for_orphaned_services()
[1520622406.982667] [001.0] [pid=23633] handle_timed_event() end
[1520622406.982673] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.982680] [001.0] [pid=23633] reschedule_event()
[1520622406.982686] [001.0] [pid=23633] add_event()
[1520622406.982692] [008.1] [pid=23633] ** Event Check Loop
[1520622406.982704] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:47 2018
[1520622406.982713] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622406.982719] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622406.982726] [001.0] [pid=23633] handle_timed_event() start
[1520622406.982731] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.982743] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_USER_FUNCTION, Run Time: Fri Mar  9 13:06:47 2018
[1520622406.982748] [008.0] [pid=23633] ** User Function Event. Latency: 0.000s
[1520622406.982754] [001.0] [pid=23633] process_host_perfdata_file()
[1520622406.982762] [001.0] [pid=23633] get_raw_command_line_r()
[1520622406.982770] [001.0] [pid=23633] process_macros_r()
[1520622406.982777] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622406.982782] [2048.1] [pid=23633] Processing: '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/$TIMET$.perfdata.host'
[1520622406.982794] [2048.1] [pid=23633]   Done.  Final output: '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/1520622406.perfdata.host'
[1520622406.982811] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622406.982821] [001.0] [pid=23633] my_system_r()
[1520622406.982837] [256.1] [pid=23633] Running command '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/1520622406.perfdata.host'...
[1520622406.982954] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622406.986263] [256.1] [pid=23633] Execution time=0.003 sec, early timeout=0, result=0, output=(null)
[1520622406.986291] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622406.986332] [001.0] [pid=23633] clear_volatile_macros_r()
[1520622406.986390] [001.0] [pid=23633] handle_timed_event() end
[1520622406.986397] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.986410] [001.0] [pid=23633] reschedule_event()
[1520622406.986414] [001.0] [pid=23633] add_event()
[1520622406.986419] [008.1] [pid=23633] ** Event Check Loop
[1520622406.986436] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:47 2018
[1520622406.986443] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622406.986449] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622406.986461] [001.0] [pid=23633] handle_timed_event() start
[1520622406.986466] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.986476] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_RESCHEDULE_CHECKS, Run Time: Fri Mar  9 13:06:47 2018
[1520622406.986481] [008.0] [pid=23633] ** Reschedule Checks Event. Latency: 0.000s
[1520622406.986487] [001.0] [pid=23633] adjust_check_scheduling() start
[1520622406.986495] [8192.0] [pid=23633] No events need to be rescheduled (0 checks in 45s window).
[1520622406.986500] [001.0] [pid=23633] handle_timed_event() end
[1520622406.986504] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.986510] [001.0] [pid=23633] reschedule_event()
[1520622406.986543] [001.0] [pid=23633] add_event()
[1520622406.986574] [008.1] [pid=23633] ** Event Check Loop
[1520622406.986603] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:47 2018
[1520622406.986624] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622406.986643] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622406.986663] [001.0] [pid=23633] handle_timed_event() start
[1520622406.986681] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.986706] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_SFRESHNESS_CHECK, Run Time: Fri Mar  9 13:06:47 2018
[1520622406.986725] [008.0] [pid=23633] ** Service Result Freshness Check Event. Latency: 0.000s
[1520622406.986745] [001.0] [pid=23633] check_service_result_freshness()
[1520622406.986762] [016.1] [pid=23633] Checking the freshness of service check results...
[1520622406.986780] [001.0] [pid=23633] handle_timed_event() end
[1520622406.986798] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622406.986870] [001.0] [pid=23633] reschedule_event()
[1520622406.986892] [001.0] [pid=23633] add_event()
[1520622406.986910] [008.1] [pid=23633] ** Event Check Loop
[1520622406.986938] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:57 2018
[1520622406.986957] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622406.986986] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622408.488553] [064.1] [pid=23633] Making callbacks (type 11)...
[1520622408.488639] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622409.990191] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622411.491345] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622412.992966] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622414.494579] [064.1] [pid=23633] Making callbacks (type 11)...
[1520622414.494672] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622415.995334] [12288.1] [pid=23633] ## Polling 979ms; sockets=8; events=11; iobs=0x1f6c140
[1520622416.975137] [001.0] [pid=23633] handle_timed_event() start
[1520622416.975185] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622416.975227] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_CHECK_REAPER, Run Time: Fri Mar  9 13:06:57 2018
[1520622416.975233] [008.0] [pid=23633] ** Check Result Reaper. Latency: 0.000s
[1520622416.975242] [001.0] [pid=23633] reap_check_results() start
[1520622416.975246] [016.0] [pid=23633] Starting to reap check results.
[1520622416.975276] [016.1] [pid=23633] Starting to read check result queue '/usr/local/nagios/var/spool/checkresults'...
[1520622416.975295] [016.0] [pid=23633] Finished reaping 0 check results
[1520622416.975299] [001.0] [pid=23633] reap_check_results() end
[1520622416.975333] [001.0] [pid=23633] handle_timed_event() end
[1520622416.975338] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622416.975345] [001.0] [pid=23633] reschedule_event()
[1520622416.975349] [001.0] [pid=23633] add_event()
[1520622416.975355] [008.1] [pid=23633] ** Event Check Loop
[1520622416.975367] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:06:57 2018
[1520622416.975389] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622416.975395] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622416.975402] [001.0] [pid=23633] handle_timed_event() start
[1520622416.975406] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622416.975416] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_STATUS_SAVE, Run Time: Fri Mar  9 13:06:57 2018
[1520622416.975420] [008.0] [pid=23633] ** Status Data Save Event. Latency: 0.000s
[1520622416.975426] [064.1] [pid=23633] Making callbacks (type 18)...
[1520622416.975457] [001.0] [pid=23633] save_status_data()
[1520622416.985689] [064.1] [pid=23633] Making callbacks (type 18)...
[1520622416.985724] [001.0] [pid=23633] handle_timed_event() end
[1520622416.985762] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622416.985792] [001.0] [pid=23633] reschedule_event()
[1520622416.985812] [001.0] [pid=23633] add_event()
[1520622416.985832] [008.1] [pid=23633] ** Event Check Loop
[1520622416.985864] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:07:02 2018
[1520622416.985883] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622416.985903] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622418.487467] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622419.989083] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622421.490325] [064.1] [pid=23633] Making callbacks (type 11)...
[1520622421.490387] [12288.1] [pid=23633] ## Polling 484ms; sockets=8; events=11; iobs=0x1f6c140
[1520622421.974926] [001.0] [pid=23633] handle_timed_event() start
[1520622421.974969] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622421.974998] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_USER_FUNCTION, Run Time: Fri Mar  9 13:07:02 2018
[1520622421.975004] [008.0] [pid=23633] ** User Function Event. Latency: 0.000s
[1520622421.975013] [001.0] [pid=23633] process_service_perfdata_file()
[1520622421.975024] [001.0] [pid=23633] get_raw_command_line_r()
[1520622421.975032] [001.0] [pid=23633] process_macros_r()
[1520622421.975038] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622421.975042] [2048.1] [pid=23633] Processing: '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/$TIMET$.perfdata.service'
[1520622421.975055] [2048.1] [pid=23633]   Done.  Final output: '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/1520622421.perfdata.service'
[1520622421.975060] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622421.975071] [001.0] [pid=23633] my_system_r()
[1520622421.975076] [256.1] [pid=23633] Running command '/bin/mv /usr/local/nagios/var/service-perfdata /usr/local/nagios/var/spool/xidpe/1520622421.perfdata.service'...
[1520622421.975091] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622421.978976] [256.1] [pid=23633] Execution time=0.003 sec, early timeout=0, result=0, output=(null)
[1520622421.979005] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622421.979109] [001.0] [pid=23633] clear_volatile_macros_r()
[1520622421.979130] [001.0] [pid=23633] handle_timed_event() end
[1520622421.979136] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622421.979145] [001.0] [pid=23633] reschedule_event()
[1520622421.979150] [001.0] [pid=23633] add_event()
[1520622421.979155] [008.1] [pid=23633] ** Event Check Loop
[1520622421.979174] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:07:02 2018
[1520622421.979179] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622421.979185] [12288.1] [pid=23633] ## Polling 0ms; sockets=8; events=11; iobs=0x1f6c140
[1520622421.979191] [001.0] [pid=23633] handle_timed_event() start
[1520622421.979209] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622421.979220] [008.0] [pid=23633] ** Timed Event ** Type: EVENT_USER_FUNCTION, Run Time: Fri Mar  9 13:07:02 2018
[1520622421.979225] [008.0] [pid=23633] ** User Function Event. Latency: 0.000s
[1520622421.979238] [001.0] [pid=23633] process_host_perfdata_file()
[1520622421.979245] [001.0] [pid=23633] get_raw_command_line_r()
[1520622421.979252] [001.0] [pid=23633] process_macros_r()
[1520622421.979257] [2048.1] [pid=23633] **** BEGIN MACRO PROCESSING ***********
[1520622421.979261] [2048.1] [pid=23633] Processing: '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/$TIMET$.perfdata.host'
[1520622421.979272] [2048.1] [pid=23633]   Done.  Final output: '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/1520622421.perfdata.host'
[1520622421.979277] [2048.1] [pid=23633] **** END MACRO PROCESSING *************
[1520622421.979292] [001.0] [pid=23633] my_system_r()
[1520622421.979298] [256.1] [pid=23633] Running command '/bin/mv /usr/local/nagios/var/host-perfdata /usr/local/nagios/var/spool/xidpe/1520622421.perfdata.host'...
[1520622421.979321] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622421.982772] [256.1] [pid=23633] Execution time=0.003 sec, early timeout=0, result=0, output=(null)
[1520622421.982800] [064.1] [pid=23633] Making callbacks (type 3)...
[1520622421.982835] [001.0] [pid=23633] clear_volatile_macros_r()
[1520622421.982890] [001.0] [pid=23633] handle_timed_event() end
[1520622421.982897] [064.1] [pid=23633] Making callbacks (type 1)...
[1520622421.982908] [001.0] [pid=23633] reschedule_event()
[1520622421.982912] [001.0] [pid=23633] add_event()
[1520622421.982917] [008.1] [pid=23633] ** Event Check Loop
[1520622421.982934] [008.1] [pid=23633] Next Event Time: Fri Mar  9 13:07:07 2018
[1520622421.982939] [008.1] [pid=23633] Current/Max Service Checks: 2/0 (inf% saturation)
[1520622421.982945] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140
[1520622423.484519] [12288.1] [pid=23633] ## Polling 1500ms; sockets=8; events=11; iobs=0x1f6c140

[tgriep]

Can you run the following in a shell in the Nagios server and post the full output?

Code: Select all

su - nagios
time /usr/local/nagios/libexec/check_esx3.pl -H 140.32.114.18 -f "/usr/local/nagiosxi/etc/components/vmware/bode_arli_hwss_hpc_mil_auth.txt" -l "CPU" -v

Thanks

[benjohns]

$ time /usr/local/nagios/libexec/check_esx3.pl -H [IP] -f "/usr/local/nagiosxi/etc/components/vmware/[HOST]_auth.txt" -l "CPU" -v
CHECK_ESX3.PL CRITICAL - SOAP request error - possibly a protocol issue: 500 read timeout


real 4m38.355s
user 0m0.582s
sys 0m0.073s

*I've tried this against multiple ESXi servers, including the one hosting our XI instance, with similar 'real' response times and the same error. The server load is negligible: load average: 0.06, 0.23, 0.44. Memory is under 50% utilization as well, so it's not a resource issue on the XI server.

[lmiltchev]

Let's rule out any corruption/mis-configuration of the "/usr/local/nagios/libexec/check_esx3.pl" plugin. Can you upload the "check_esx3.pl" plugin from your machine to the forum? We will review/test it in-house.

Note: You may need to rename it to check_esx3.txt file, prior to uploading it to the forum.

What is the version of the vmware client/server that you are running your check against? What is the version of the SDK that you installed on the Nagios XI server (5.5, 6.0, 6.5)?