背景:服务器跑Python脚本收集交易日志,发送到后台分析并存储到cassanda数据库
现象:某一不确定时间,脚本会假死(进程并没有停),实际已经不干活了,也不打日志,并且所有服务器的脚本都几乎同一时间假死,怎会如此一致呢?
分析:
一、检查脚本
1)发现脚本日志总是在出现若干次的Connection异常后,进程会假死
异常1:<urlopen error [Errno 104] Connection reset by peer>
说明:常见的有几种情况,1、服务器的并发连接数超过了最大值,服务器会将该连接关闭 ;2、客户关闭请求,而服务器还在给客户端发送数据
【reset日志】
2013-02-01 15:11:25,897 logtail.py [line:49] [INFO] worker:ORDER_SUCCESS,job is waiting...
2013-02-01 15:11:30,895 logtail.py [line:60] [INFO] worker:ORDER_SUCCESS,start job at 2013-02-02 15:11:30
2013-02-01 15:11:30,896 jobworker.py [line:161] [INFO] collect...
2013-02-01 15:11:30,911 jobworker.py [line:179] [INFO] send...
2013-02-01 15:11:30,912 jobworker.py [line:45] [INFO] http://110.75.14.162:8000/wirelesscrm/log/insertLog.do
2013-02-01 15:11:30,914 jobworker.py [line:52] [ERROR] <urlopen error [Errno 104] Connection reset by peer>
2013-02-01 15:11:30,914 jobworker.py [line:134] [INFO] ok=0, notok=1, sum=19
2013-02-01 15:11:30,930 logtail.py [line:67] [INFO] worker:ORDER_SUCCESS,job is done at 2013-02-02 15:11:30
异常2: <urlopen error [Errno 110] Connection timed out>
说明:最大可能性也是连接数太少,还有后台响应太慢,但服务器都很正常,也没有发布或重启
【timeout日志】
2013-02-01 15:11:35,928 logtail.py [line:60] [INFO] worker:ORDER_SUCCESS,start job at 2013-02-02 15:11:35
2013-02-01 15:11:35,928 jobworker.py [line:161] [INFO] collect...
2013-02-01 15:11:35,943 jobworker.py [line:179] [INFO] send...
2013-02-01 15:11:35,945 jobworker.py [line:45] [INFO] http://110.75.14.162:8000/wirelesscrm/log/insertLog.do
2013-02-01 15:14:44,944 jobworker.py [line:52] [ERROR] <urlopen error [Errno 110] Connection timed out>
2013-02-01 15:14:44,944 jobworker.py [line:134] [INFO] ok=0, notok=1, sum=25
2013-02-01 15:14:44,959 logtail.py [line:67] [INFO] worker:ORDER_SUCCESS,job is done at 2013-02-02 15:14:44
2)修改脚本,通过日志可以看到一个线程运行了有3分钟的时间,因此脚本设置连接超时时间,f = urllib2.urlopen(url, timeout=1),设置为1s,在1台机器上运行了几天,经过观察,暂未发现上面的异常日志。
二、检查后台系统wcrm的apache配置,貌似找到了原因
apache的配置如下:
ServerTokens Prod
ServerSignature Off
Timeout 45
KeepAlive On
MaxKeepAliveRequests 20
KeepAliveTimeout 3
SendBufferSize 640000
说明:KeepAlive On是开启KeepAlive支持,KeepAliveTimeout决定一 个KeepAlive的连接能保持多少时间,Timeout后就关闭连接,若还有数据必须再建立新的连接 了,MaxKeepAliveRequests是最多服务多少个请求就关闭连接。显然这里设置的连接数20太少,但一般后台也没什么人用,然后再看apache日志,存在大量的自检请求,这样一来,确实没有多少连接可用了。。。
【apache日志】
72.24.90.154 541 - [02/Feb/2013:19:50:23 +0800] "GET http://172.24.53.113/crm/status.taobao" 200 - "-" "KeepAliveClient"
总结:为什么脚本同一时间停止的原因终于找到了,crm线上只有2台机器,交易服务器则有n多台,在某个时间当连接数不够用时,这样后面的请求都会失败,而所有机器的脚本线程一直处于等待响应状态,抛出异常后http资源没有释放(为什么没释放,是什么情况??这里需要深入了解一下),增加关闭http资源代码:response = urllib2.urlopen(req,timeout=10) response.close()