apache异常分析全过程

关于apache中的异常:

现象:
1、 10.49.4.61 的httpd访问不了,但是访问却又不是立即退出,而是一直等待
2、 10.49.4.61 的httpd子进程240个,不再变化
3、 netstat 发现很多close_wait 的连接; 就是客户端已经断开,但是服务器还没有断开的情况 

分析:
1. tcpdump 发现连接已建立,也发送了一些请求数据,接着就什么也没有了; 说明请求并没有被apache子进程给接走
2. netstat 查看一下,发现Recv-Q 里面确实有数据
3. strace httpd子进程发现每个子进程都如下:
 write(11, "10.49.4.21 – – [12/Jul/2009:10:2"…, 101 <unfinished …>

 显然,要写apache日志,而且是今天10点20多时的日志,但是被某种原因给阻塞了,下面就是要知道为什么阻塞了
4. 看一下fd = 11 是个什么东西:
 [root@sso115 htdocs]# ll /proc/17151/fd/
 total 0
 lr-x—— 1 root root 64 Jul 12 10:53 0 -> /dev/null
 l-wx—— 1 root root 64 Jul 12 10:53 1 -> /dev/null
 lr-x—— 1 root root 64 Jul 12 10:53 10 -> eventpoll:[41846266]
 l-wx—— 1 root root 64 Jul 12 10:53 11 -> pipe:[41551707]
 lrwx—— 1 root root 64 Jul 12 10:53 12 -> socket:[41846267]
 l-wx—— 1 root root 64 Jul 12 10:53 13 -> pipe:[41551708]
 l-wx—— 1 root root 64 Jul 12 10:53 2 -> /data1/apache2/logs/error_log
 lrwx—— 1 root root 64 Jul 12 10:53 3 -> socket:[39585452]
 lrwx—— 1 root root 64 Jul 12 10:53 4 -> socket:[39585453]
 lr-x—— 1 root root 64 Jul 12 10:53 5 -> pipe:[41551704]
 l-wx—— 1 root root 64 Jul 12 10:53 6 -> pipe:[41551704]
 l-wx—— 1 root root 64 Jul 12 10:53 7 -> /data1/apache2/logs/access_log
 l-wx—— 1 root root 64 Jul 12 10:53 8 -> pipe:[41551705]
 l-wx—— 1 root root 64 Jul 12 10:53 9 -> pipe:[41551706]

 原来是个管道,可能是管道写满了;那么这个管道是做什么的呢?

5. 应该是和rotatelogs程序共有的pipe,验证如下:
 rotatelogs 只剩下三个进程了,应该有四个呢,肯定被谁误杀了一个!!!
 [root@sso115 ~]# ps aux | grep rot                    
 root     29709  0.0  0.0  61116   736 pts/1    S+   14:04   0:00 grep rot
 root     31469  0.0  0.0  23524   696 ?        S    Jul10   0:00 /data1/apache2/bin/rotatelogs /data1/apache2/logs/%Y%m/online.internal.sina.com.cn-80-error_log.%Y%m%d 86400 480
 root     31470  0.0  0.0  23524   692 ?        S    Jul10   0:00 /data1/apache2/bin/rotatelogs /data1/apache2/logs/%Y%m/online.sso.sina.com.cn-80-error_log.%Y%m%d 86400 480
 root     31472  0.0  0.0  23524   692 ?        S    Jul10   0:00 /data1/apache2/bin/rotatelogs /data1/apache2/logs/%Y%m/online.sso.sina.com.cn-80-access_log.%Y%m%d 86400 480
 [root@sso115 ~]#
 
 每个进程里面都没有这个管道
 [root@sso115 ~]# ll /proc/31469/fd
 total 0
 lr-x—— 1 root root 64 Jul 12 10:53 0 -> pipe:[41551705]
 l-wx—— 1 root root 64 Jul 12 10:53 1 -> /dev/null
 l-wx—— 1 root root 64 Jul 12 10:53 2 -> /data1/apache2/logs/error_log

 [root@sso115 ~]# ll /proc/31470/fd
 total 0
 lr-x—— 1 root root 64 Jul 12 10:53 0 -> pipe:[41551706]
 l-wx—— 1 root root 64 Jul 12 10:53 1 -> /dev/null
 l-wx—— 1 root root 64 Jul 12 10:53 2 -> /data1/apache2/logs/error_log
 [root@sso115 ~]#

 [root@sso115 ~]# ll /proc/31472/fd
 total 0
 lr-x—— 1 root root 64 Jul 12 10:53 0 -> pipe:[41551708]
 l-wx—— 1 root root 64 Jul 12 10:53 1 -> /dev/null
 l-wx—— 1 root root 64 Jul 12 10:53 2 -> /data1/apache2/logs/error_log
 [root@sso115 ~]#

 显然,那个rotatelogs进程肯定是被谁给杀掉了,或者是出现意外死亡了;
 查了一下系统log,有看了一下用户的.bash_history 都没有发现和rotatelogs相关的信息

6. 没法查下去了,不过可以做一个测试,就是把rotatelogs进程杀掉,是否就肯定出现这种现象
 使用graceful的办法重启apache,原以为不能凑效,因为请求都是为处理完的,而且不可能处理完的;但是还是都死掉了

7. 重启apache,两个虚拟机,四个rotatelogs 进程; 试图杀死一个rotatelogs进程,但总是立即又出现了一个新的,以为该进程具有自派生机制,
 就用 kill -9 来杀,结果还是立即重新启动一个;
 观察了一下新的进程的ppid,发现时apache守护进程的pid,于是用strace监视一下apache的守护进程; 因为rotatelogs 进程是apache守护
 进程的子进程,所以rotatelogs进程死掉的时候会给apache守护进程发送一个信号,apache守护进程就可以根据自己保存的管道在启动一个
 rotatelogs进程,于是这个进程就有了杀不死的功能了。
 可以用这个办法做杀不死进程。
 
 跟踪apache守护进程的主要信息
 22934 14:34:35.057195 wait4(-1, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGKILL}], WNOHANG|WSTOPPED, NULL) = 31358
 22934 14:34:35.057365 write(2, "piped log program \’/data1/apache"…, 154) = 154
 22934 14:34:35.057490 dup(10)           = 14
 22934 14:34:35.057561 dup(11)           = 15
 22934 14:34:35.057619 dup(1)            = 16
 22934 14:34:35.057689 dup(2)            = 17
 22934 14:34:35.057893 access("/data1/apache2/bin/rotatelogs", X_OK) = 0
 22934 14:34:35.057991 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x2aaaab123c70) = 31463

留下评论

邮箱地址不会被公开。 必填项已用*标注

此站点使用Akismet来减少垃圾评论。了解我们如何处理您的评论数据