Python实战2-Python脚本同一时间假死可能原因分析

 

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