我前面写了几篇文章,讲c3p0数据库连接池发生了连接泄露,但是随机出现,难以确定根因,最终呢,为了快速解决问题,我是先写了个shell脚本,脚本主要是检测服务的接口访问日志,看看过去的30s内是不是接口几乎都超时了,如果是的话,咱们就重启服务。然后把这个shell加入到了crontab里,每30s调度一次。
crontab如下(cron最小调度时间为分钟,所以搞了两条,以支持30s执行一次):
* * * * * /bin/sh /xxx/xxx/check_service_block_gbk.sh
* * * * * sleep 30; /xxx/xxx/check_service_block_gbk.sh
脚本的内容大概如下,:
计算过去n秒内异常请求的次数
...
如果异常请求超过某个阈值,重启服务
if [ "${error_req_count_sum}" -gt ${THRESHOLD_FOR_ERROR_REQ_IN_LAST_N_SECONDS} ];then
log "trigger restart, start restart"
"${SERVICE_ROOT_PATH}"/run.sh stopall
"${SERVICE_ROOT_PATH}"/run.sh startall
log "finish restart,finish current check"
else
log "no need restart,finish current check"
fi
这个脚本上线有半个多月了,这期间问题一直没复现,结果,昨天下午,运维同事和我说,用户反馈app出问题了,也就是问题复现了,但是,我那个脚本吧,好像有问题,现象就是,异常进程是结束了,但是,却没有启动起来,导致这期间服务完全宕了,最后还是他手动启动起来的。
由于事情是事后他和我说的,我过去后也就是一起看了下日志,发现服务的访问日志确实是中断了2分钟(就是服务被脚本干掉后,没启动起来的真空期)。而shell脚本呢,在如下几行中:
function log()
{
now=$(date "+%Y-%m-%d %H:%M:%S")
echo -e "$now : $*"
echo "$now : $*" >> "${SERVICE_ROOT_PATH}"/check_service_block_gbk.log
}
log "trigger restart, start restart"
"${SERVICE_ROOT_PATH}"/run.sh stopall
"${SERVICE_ROOT_PATH}"/run.sh startall
log "finish restart,finish current check"
当时脚本写得不算很完备,只有log的那两行有日志,真正执行停止服务和启动服务的run.sh的执行,日志都打到console去了,日志文件里完全没有:
"trigger restart, start restart"
"finish restart,finish current check"
所以啊,毕竟还是不够专业,应该把脚本的标准输出重定向到日志文件的。
另外,根据脚本和现象,确定是执行了/run.sh stopall的,毕竟服务都没了嘛。
我们这个服务的框架很老,但也还比较稳定,框架自带的脚本就是上面看到的那个run.sh,这个run.sh呢,执行run.sh startall
,会启动3个服务。
这几个服务一启动后,就会在当前目录下,生成几个pid文件:
而停止的时候run.sh stopall
,就会根据上面的几种方法去找到对应的pid来kill。然后这几个服务的框架是支持kill -9这种暴力杀服务的,所以,几个服务被stop了,日志里是一点信息没有;然后呢,既然你说服务没启动起来,难道启动日志也没有嘛?问题是,还真的没有,空空如也,正常的话,自然是有的。但是我们可能就是执行run.sh startall
时,报错可能都写到标准输出了,自然就没记录到日志里。
当时看到的东西,差不多就是这些。
有的人会说,感觉这脚本没测试,直接就上线了,我可以这么说,测试,肯定是测了的,本地运行shell,都能把服务重启起来;但是,把脚本放到crontab里面后,倒是没有测试过这个分支。
这两个脚本是在同一目录下:
[root@xxxx]# ll check_service_block_gbk.sh run.sh
-rwxr-xr-x 1 root root 3498 Aug 1 08:50 check_service_block_gbk.sh
-rwxr-xr-x 1 root root 11425 Aug 1 10:51 run.sh
我当时测试的时候,在本地测是通过如下命令,一点问题没有:
./check_service_block_gbk.sh
结果这次上线又出了这个,我就想着在本地复现下,弄到cron里去触发,没想到,还真的和线上一样,服务被stop了,但是并没有重启起来。
我先是crontab -e
加了日志,把脚本的标准输出重定向到文件/root/cron.log:
* * * * * /bin/sh -x /foo/bar/check_service_block_gbk.sh >> /root/cron.log 2>&1
然后触发了一次后,去查看shell执行日志/root/cron.log,发现,在执行startall
时,nohup启动服务的地方,看着有点怪:
+ nohup /foo/bar/TBAServer
这个TBAServer是个二进制,就是我们的后台服务。我当时,为啥感觉有点怪呢,因为run.sh中,nohup那一行如下:
nohup $SERVER_PATH >> ${SERVER_DIR}/stdout.txt 2>&1 &
我们脚本里,后面还有>> xxx/stdout.txt 2>&1 &
这些,为啥在shell -x的执行log里没有呢?
当时以为找到了问题,结果后来,我正常在shell中如下执行:
sh -x check_service_block_gbk.sh
发现执行日志也是一样的,看起来不是这个的问题。
然后左查右查,搞了好久,反正昨晚没弄出来,然后早上上班的时候,在互联网上关键字找了下,好像也没有类似的问题,只看到说,在cron执行的话,环境变量和在shell中执行不一样,不过我还没来得及测试环境变量这块,就有了新发现。
由于昨晚那台本地拿来复现的机器,白天用的人较多,为了不影响别人,我就换了台机器,没想到,换到新机器后测试时,在shell的执行日志中看到了关键日志:
+ nohup /foo/bar/TBAServer
...
启动路径不是进程所在路径,系统无法正常运行
看到这个,我大概就知道是啥原因了,为啥这个关键日志,在昨晚的机器没有呢,是因为二进制文件的版本不同,我今天这台机器上的二进制,版本更新。
看到这个错误,我大概猜测是进程的current working directory的问题,于是我修改了下run.sh,打印pwd。
echo cwd: "$PWD" ---增加的一行
nohup $SERVER_PATH >> ${SERVER_DIR}/stdout.txt 2>&1 &
然后,分别测试在shell下正常运行和通过crontab运行:
crontab时,
cwd: /root
shell正常运行时:
cwd: /foo/bar
虽然已基本确认问题,我还是进一步检验了一下,为啥二进制文件里会报那个错误,我用IDA对那个二进制反编译了一下,(只能看懂一点,非常勉强)。
里面有如下代码:
if ( !IsStartFromPFPath() )
{
OUT(byte_4AB1C0);
exit(1);
}
这里调用了一个函数,大意是是否从xxx路径启动,不是的话,就会输出一个信息,然后exit。
这个输出的信息,我找了下,确实就是日志里那句。
接下来,我们进函数一览,现在看c++已经非常吃力了,只能看个大概:
这里面调用了另外两个函数,一个是获取进程的cwd(当前工作目录),一个是获取进程文件的路径,然后做比较,看看是否一致。
这个获取进程文件路径的函数,如上,我们结合猜测,应该就是获取二进制文件TBAServer的位置。
而,我们在cron执行时,cwd为/root,而TBAServer的位置为/foo/bar/TBAServer,这两个路径,明显不一致,所以,最终报了那个错误,导致启动失败。
为了进一步确认以上猜想,我准备使用strace命令,来看看启动这个TBAServer时,到底进行了哪些系统调用?
我改了run.sh,如下:
echo cwd: "$PWD"
nohup strace -q -f -s 200 $SERVER_PATH 2>&1 & >> ${SERVER_DIR}/stdout.txt
strace命令的强大毋庸置疑,可以跟踪系统调用,很多难题都能迎刃而解。下图也确认了我们的代码分析的结论。
知道是cwd的问题了,那就解决吧,解决的办法就是要将工作目录切换到正确的目录,我采用的方法是直接在crontab这里修改。
* * * * * cd /foo/bar; /bin/sh -x /foo/bar/check_service_block_gbk.sh
有一个小问题是,这里我就没再将执行日志重定向了,也就是去掉了下面这部分。因为我发现服务运行时的日志也会打印进去,到时候日志就打了两份了。暂时还没去想怎么解决。
>> /root/cron.log 2>&1
下午的时候,到运维同事那边试了试,运行很平稳,检测到异常就可以自动重启了,终于可以了了这个事了。
关于cron环境变量问题的文章: