关于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