Nagios+Ndoutils故障排查实例

sangyb86

   我属于比较笨的人，这种排错的方法虽然奏效，但是很消耗时间和精力，我并不推荐这种方式来排错，写出来纯粹是分享，如果有兴趣，大家可以看一下。
   前两天，有同事在nagios上配了ndo，但是从昨晚开始，那台配过ndo的nagios出现了很奇怪的现象，没法重启！执行/etc/init.d/nagios restart的时候，没有任何出错的提示，就一直停着，今天正好有空，就排查了一下。
   配置好ndomod，方式是tcp，重启nagios，起不来……
   换成文件的方式，重启nagios，成功……
   怀疑是ndomod的问题，再换成tcp方式，重启nagios，依旧卡住。
   首先看nagios.log，输出如下
[1238524265] Nagios 3.0.1 starting... (PID=27384)
[1238524265] Local time is Wed Apr 01 02:31:05 CST 2009
[1238524265] LOG VERSION: 2.0
[1238524265] ndomod: NDOMOD 1.4b7 (10-31-2007) Copyright (c) 2005-2007 Ethan Galstad (
nagios@nagios.org
)
[1238524265] ndomod: Successfully connected to data sink.  0 queued items to flush.
[1238524265] Event broker module '/opt/nagios/bin/ndomod-3x.o' initialized successfully.
   接下来本来应该是输出一行Finished daemonizing，然后把pid给我打出来，但是在这里就没有了，看不出有什么地方出错。
   于是打开debug，因为ndomod属于event broker，所以debug_level=64。
   重启，看nagios.debug，输出如下
[1238521527.004242] [064.0] [pid=25720] Module '/opt/nagios/bin/ndomod-3x.o' loaded with return code of '0'
[1238521527.004259] [064.0] [pid=25720] nebmodule_deinit() found
   看来mod本身载入没有问题，mod的代码本身也不会有问题，再往下看
[1238521527.004271] [064.1] [pid=25720] Making callbacks (type 7)...
[1238521527.166395] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166484] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166583] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166632] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166681] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166736] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166783] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166839] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166890] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166938] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.166992] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167039] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167254] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167304] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167351] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167417] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167465] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167511] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167557] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167603] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167652] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167698] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167746] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167806] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.167853] [064.1] [pid=25720] Making callbacks (type 9)...
[1238521527.173034] [064.1] [pid=25720] Making callbacks (type 9)...
   这里往下没有了，可见，是因为nagios调用了ndomod的某个回调的函数，以至于卡住了。
   具体是卡在什么地方，现在还不清楚，于是打开nagios的源代码，从nagios.c开始往下看。
   main函数的开始，是处理一些参数，-v，-p，-d之类的，我要看的是-d的参数，所以直接从599行开始看了。
   没啥难度，所有daemon进程都差不多，读主配置文件，打开debug文件，放弃权限，然后读入mod的callback表。
   接下来，在638行就看到了我们的第一行日志：
logit(NSLOG_PROCESS_INFO,TRUE,"Nagios %s starting... (PID=%d)\n",PROGRAM_VERSION,(int)getpid());
   在这行日志的时候，系统都是正常的，于是继续跳着看。
asprintf(&buffer,"Local time is %s\n",datestring);
   这是第二行日志。
   看到这里小心了，633行调用了neb_load_all_modules()函数，载入所有的mod，在目录里找一下，在base/nebmods.c里
找到这个函数，发现这个函数是逐个调用下面的neb_load_module函数，看着注释往下走，大概明白基本步骤，就是把mod先拷贝一个副本，然后
再从副本里读出它的init函数，然后把副本删掉，最后运行init函数，同时取得deinit函数。init就是初始函数了，deinit就是退出的函
数。如果中间有错，或者权限没开，就返回失败，因为我们看到nagios已经开始调用callback函数了，所以这步应该也没有问题。
   然后到ndo的 源码里，找到ndomod.c，它的第一个函数，就是被nagios调用的初始化函数了，也可以看到它打出来的 日志：
snprintf(temp_buffer,sizeof(temp_buffer)-1,"ndomod: %s %s (%s) Copyright (c) 2005-2007 Ethan Galstad (
nagios@nagios.org
)",NDOMOD_NAME,NDOMOD_VERSION,NDOMOD_DATE);
   最后调用ndomod_init才是真正的初始化函数，继续跟踪，就可以看到它读入缓存文件，然后打开data
sink，还说了个hello，然后是注册callback函数，在ndomod_register_callbacks()函数中，可以发现
ndomod注册的所有callback函数都只有一个，ndomod_broker_data，也好记，省的麻烦。
   因为我们已经在debug中看到了nagios调用callback，所以这步应该也是没问题的。
   小心了！！！注释一：
   继续返回nagios的源码，下一步就是broker_program_state(NEBTYPE_PROCESS_PRELAUNCH,NEBFLAG_NONE,NEBATTR_NONE,NULL);
   看名字好像是对mod进行下预载入，搜这个函数，在base/broker.c中找到它，可以看到它就是做了些参数的传递，然后调用了
neb_make_callbacks(NEBCALLBACK_PROCESS_DATA,(void
*)&ds)，因为我们基本确定是在某个callback中被卡住了，所以接下来，肉戏就要来了。
   仔细找下，NEBCALLBACK_PROCESS_DATA的真实值是7，ds里面的一些参数只有type是上个函数传过来的，可以找到
NEBTYPE_PROCESS_PRELAUNCH是104，至于那两个NONE，不用想也知道，不是0就是空，反正没用。最后一个是当前的时间戳。
   然后找neb_make_callbacks函数，在base/nebmods.c中找到，可以看到这家伙也没什么技术含量，直接把两个参数传给
callbackfun，我们的callbackfun只有一个，废话少说，直接到ndo里去看ndomod_broker_data()。
   这个函数有点长，但是一般来讲，越是长的函数，越容易明白它是做什么的，两个参数，event_type和data都是直接传来的，event_type是7，data->type是104，还有个时间戳，别的都没有了。
   下来很快就发现，是个event_type的case语句，第一种情况就让我们遇上了，自己看那个if条件，if(!(ndomod_process_options & NDOMOD_PROCESS_PROCESS_DATA))
   在代码最开头可以找到这个：
unsigned long ndomod_process_options=NDOMOD_PROCESS_EVERYTHING
   这个值是-1，可以忽略了，看下一个，搜一下，可以找出来NDOMOD_PROCESS_PROCESS_DATA
其实就是1，他们两个按位与，结果也是1，然后再非……条件不满足，跳出case语句往下看。下面居然还是一个event_type的case语句，同样
的，第一种情况还让我们遇上了。下面是往dbuf里面加一大堆东西，我比较感兴趣，于是就查了一下，结果大概是这样的：
202:
1=300
2=0
3=0
4=1238522028.423596
73=1238522028
74=262144
72=ndomod: Warning - No file rotation command defined.
999
   这步还是正常的，继续往下看，跳出case以后，最后把dbuf传给了ndomod_write_to_sink(dbuf.buf,NDO_TRUE,NDO_TRUE);
   仔细看下这个函数，其实也没啥，就是看看sink打开了没，如果没打开，就打开，然后调用ndo_sink_write把传过来的字串传过去，类似写fd了。
   这里打开sink应该没问题的，因为我们看到了它打出来的日志：
asprintf(&temp_buffer,"ndomod: Successfully flushed %lu queued items to data sink.",items_to_flush);
   写数据的函数在这个文件里找不到了，在io.c里，我觉得这个应该属于比较底层一点的，就先略过，先往下看。
   一路返回那一大串的case语句，结束了第二个case，往下还有一个case语句，还是event_type，还是第一个。
   一个if语句，如果我们传过来的type等于NEBTYPE_PROCESS_START再往下执行，我们传来的type是104，而这个是100，第二个if语句，是跟105比较，比较都失败了，所以，跳出case，返回nagios的代码里。
   ！！！我们返回注释一：
   这么一大串有意义无意义的调用，其实就做了一件事，打开sink，往里面传了一串以200开头的数据，除了最后一步io的部分可能会有点问题，别的部分我们还没看出什么问题来。
   继续向下，下面就是检查object配置文件了，因为我的日志里还有些object的warning信息，所以我确认，这里往上都是正常的，排除了io.c文件里的代码卡住的可能。
   还是一些常用的处理，直到另一个broker
broker_program_state(NEBTYPE_PROCESS_START,NEBFLAG_NONE,NEBATTR_NONE,NULL);
   和我们上次的调用基本一样，只有第一个参数不一样了，查一下，就会发现，第一个参数的值居然是100，我们立刻想起了第三个case语句里的第一个if条件，不就是和100做比较么？这次就简单一点，单刀直入好了，直接看那个if条件满足后，要执行哪些函数。
   先别着急，再往下扫一眼，就会发现，执行完这个函数后，在732行，立刻就会打这样的日志：
asprintf(&buffer,"Finished daemonizing... (New PID=%d)\n",(int)getpid());
   我的nagios启动的时候，是没有这行日志打出来的，所以，问题肯定在这个之前，那也只有在这个函数里了。到ndo里，看那个现在我们已经满足了的if条件语句。
   满足了if条件后，执行两个函数：
   第一个函数是ndomod_write_config_files，参数是空。它也只是调用别的两个函数，ndomod_write_config_files和ndomod_write_resource_config_files。
ndomod_write_resource_config_files里，看样子是没啥问题
的，ndomod_write_resource_config_files直接返回成功。
   于是看第二个函数ndomod_write_config(NDOMOD_CONFIG_DUMP_ORIGINAL)。传递的参数，查过后发现是1。传到ndomod_write_config里，那config_type就是1了。
   这个函数大致看下，也比较简单，就是往sink里面写个头，写个尾，中间调用了ndomod_write_object_config(config_type)，参数一样，是1。
   我们可以接着往下看，在ndomod_write_object_config这个函数里面，看到了点猫腻，光在函数开头定义的变量就有几十个，继续往下
看，这家伙的代码长达一千多行，而且里面全部是循环，每个循环里，都有对sink的写入操作，如果不是它慢，那还能有谁呢？其实看看名字也明白了，这个东
西，就是把nagios所有的配置项都导出来，传到sink里的函数，我的nagios里的配置项有点多，光service就近万，host近两千，还不算别的，被它卡住，那是及有可能的。
   回到ndomod_write_config里再仔细看，有一个判断条件：
   if(!(ndomod_config_output_options & config_type))
   如果这个条件满足，则直接返回，下面的1500行代码可以不用执行，config_type
是1，ndomod_config_output_options虽然不知道它是几，但是看看配置文件，也就猜得出来它是谁了，不就是最后一个选
项，config_output_options么，我定义的是3，3和1按位相与，得出的结果是1，非一下就成了0，只能继续往下执行……
   在ndomod_write_object_config里，也看到了两个类似的if语句，如果条件满足，就可以直接返回，第一个是和
process_option相与的，我的process_option是-1，所以也就不指望它了。第二个判断和上面那个函数中的判断一模一样，上面的
我不满足，这个肯定也不满足。
   原因大概也就猜到了，就是因为我process_option设置了-1，还有
config_output_option设置了3，所以导致每次启动nagios的时候都会执行这么长的函数，有时候网络环境不好或者别的原因，这里就
被卡死了，但是因为没有任何错误，所以从日志和debug里也看不出任何错来。
   于是我把config_output_option的值改成2，2和1按位相与，结果是0，就直接返回，不会执行下面的大函数了。改过配置后，重启nagios，正常启动，看来运气不错，就是它的问题。
   前后耗时2个小时，终于找到了问题所在……办法是笨了点，但是通过看源码，也明白了不少以前不明白的地方，比如说mod的调用方式，其实就是注册一个callback函数列，然后nagios再调用这个序列中的函数，到mod里执行。
               
               
               

本文来自ChinaUnix博客，如果查看原文请点：http://blog.chinaunix.net/u2/89218/showart_2019591.html