背景:服务器跑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()