线上问题排查--进程重启失败,最后发现是忘了cd

问题,排查,进程,重启,失败,最后,发现,cd · 浏览次数 : 212

小编点评

**问题** 在cron执行过程中,进程的cwd不是正确的目录,导致启动失败。 **分析** 问题根源在于`if ( !IsStartFromPFPath() )``的代码,该代码检查是否从xxx路径启动进程。由于`$SERVER_PATH`是一个包含二进制文件的路径,当cwd不是xxx路径时,该代码会报错误。 **解决方案** 将工作目录切换到正确的目录。 ``` * * * * * cd /foo/bar; /bin/sh -x /foo/bar/check_service_block_gbk.sh ``` **注意** 在代码中,`/root/cron.log`和`/root/cron.log`的用法可能导致错误,建议使用`/root/cron.log`。

正文

背景

我前面写了几篇文章,讲c3p0数据库连接池发生了连接泄露,但是随机出现,难以确定根因,最终呢,为了快速解决问题,我是先写了个shell脚本,脚本主要是检测服务的接口访问日志,看看过去的30s内是不是接口几乎都超时了,如果是的话,咱们就重启服务。然后把这个shell加入到了crontab里,每30s调度一次。

image-20230801204455638

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个服务。

  • 一个是服务本身
  • 再一个是一个定时重启脚本,脚本里是一个死循环,每次循环就是检测是否到指定时间了,如果到了,就重启服务;没到,就sleep 1s;
  • 另一个也是一个watchdog脚本,脚本里是一个死循环,每次循环就是检测服务还在不在,不在了就把服务拉起来

这几个服务一启动后,就会在当前目录下,生成几个pid文件:

  • 服务本身,不生成pid文件,停止时就靠服务名去ps -ef|grep来查找
  • 定时重启脚本,生成pid到reset.pid这个文件
  • watchdog脚本,生成pid到watchdog.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。

这个输出的信息,我找了下,确实就是日志里那句。

image-20230801221018292

接下来,我们进函数一览,现在看c++已经非常吃力了,只能看个大概:

image-20230801221113482

这里面调用了另外两个函数,一个是获取进程的cwd(当前工作目录),一个是获取进程文件的路径,然后做比较,看看是否一致。

image-20230801221244505

这个获取进程文件路径的函数,如上,我们结合猜测,应该就是获取二进制文件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命令的强大毋庸置疑,可以跟踪系统调用,很多难题都能迎刃而解。下图也确认了我们的代码分析的结论。

image-20230801222823622

问题解决

知道是cwd的问题了,那就解决吧,解决的办法就是要将工作目录切换到正确的目录,我采用的方法是直接在crontab这里修改。

* * * * * cd /foo/bar; /bin/sh -x /foo/bar/check_service_block_gbk.sh 

有一个小问题是,这里我就没再将执行日志重定向了,也就是去掉了下面这部分。因为我发现服务运行时的日志也会打印进去,到时候日志就打了两份了。暂时还没去想怎么解决。

>> /root/cron.log 2>&1  

下午的时候,到运维同事那边试了试,运行很平稳,检测到异常就可以自动重启了,终于可以了了这个事了。

参考文章

关于cron环境变量问题的文章:

https://mp.weixin.qq.com/s/Qafz20Mum51yY7OjfRpywA

https://mp.weixin.qq.com/s/9dWlgS4YslC6MnXbF2E8rw

与线上问题排查--进程重启失败,最后发现是忘了cd相似的内容:

线上问题排查--进程重启失败,最后发现是忘了cd

# 背景 我前面写了几篇文章,讲c3p0数据库连接池发生了连接泄露,但是随机出现,难以确定根因,最终呢,为了快速解决问题,我是先写了个shell脚本,脚本主要是检测服务的接口访问日志,看看过去的30s内是不是接口几乎都超时了,如果是的话,咱们就重启服务。然后把这个shell加入到了crontab里,

[转帖]线上大量CLOSE_WAIT的原因深入分析

这一次重启真的无法解决问题了:一次 MySQL 主动关闭,导致服务出现大量 CLOSE_WAIT 的全流程排查过程。 近日遇到一个线上服务 socket 资源被不断打满的情况。通过各种工具分析线上问题,定位到问题代码。这里对该问题发现、修复过程进行一下复盘总结。 先看两张图。一张图是服务正常时监控到

[转帖]线上Java 高CPU占用、高内存占用排查思路

一、前言 处理过线上问题的同学基本上都会遇到系统突然运行缓慢,CPU 100%,以及Full GC次数过多的问题。当然,这些问题的最终导致的直观现象就是系统运行缓慢,并且有大量的报警。本文主要针对系统运行缓慢这一问题,提供该问题的排查思路,从而定位出问题的代码点,进而提供解决该问题的思路。 二、分析

debug技巧之远程调试

一、前言 大家好啊,我是summo,今天给大家分享一下我平时是怎么调试代码的,不是权威也不是教学,就是简单分享一下,如果大家还有更好的调试方式也可以多多交流哦。 当我们的应用发布到线上之后,就不能随意启停了,但如果线上出现了BUG怎么办呢?大多数时候我们会借助线上打印的日志进行排查问题,如果幸运的话

记一次 Redisson 线上问题 → ERR unknown command 'WAIT' 的排查与分析

开心一刻 昨晚和一个朋友聊天 我:处对象吗,咱俩试试? 朋友:我有对象 我:我不信,有对象不公开? 朋友:不好公开,我当的小三 问题背景 程序在生产环境稳定的跑着 直到有一天,公司执行组件漏洞扫描,有漏洞的 jar 要进行升级修复 然后我就按着扫描报告将有漏洞的 jar 修复到指定的版本 自己在开发

MySQL innoDB 间隙锁产生的死锁问题

线上经常偶发死锁问题,当时处理一张表,也没有联表处理,但是有两个mq入口,并且消息体存在一样的情况,频率还不是很低,这么一个背景,我非常容易怀疑到,两个消息同时近到这一个事务里面导致的,但是是偶发的,又模拟不出来什么场景会导致死锁,只能进行代码分析,问题还原的方式去排查问题。

[转帖]kubelet 原理解析五: exec的背后

https://segmentfault.com/a/1190000022163850 概述 线上排查pod 问题一般有两种方式,kubectl log或者kubectl exec调试。如果你的 log 写不够优雅,或者需要排除网络问题必须进容器,就只能 exec 了。 # 在pod 123456-

线上FullGC问题排查实践——手把手教你排查线上问题

作者:京东科技 韩国凯 一、问题发现与排查 1.1 找到问题原因 问题起因是我们收到了jdos的容器CPU告警,CPU使用率已经达到104% 观察该机器日志发现,此时有很多线程在执行跑批任务。正常来说,跑批任务是低CPU高内存型,所以此时考虑是FullGC引起的大量CPU占用(之前有类似情况,告知用

[转帖]GC Ergonomics间接引发的锁等待超时问题排查分析

https://www.cnblogs.com/micrari/p/8831834.html 1. 问题背景 上周线上某模块出现锁等待超时,如下图所示:我虽然不是该模块负责人,但出于好奇,也一起帮忙排查定位问题。 这里的业务背景就是在执行到某个地方时,需要去表中插入一批数据,这批数据需要根据数据类型

ELK日志缺失问题排查-多行日志聚合Logstash配置问题

1. 背景 推荐系统的推荐请求追踪日志,通过ELK收集,方便遇到问题时,可以通过唯一标识sid来复现推荐过程 最近在碰到了几个bad case,需要通过sid来查询推荐日志,但发现部分无法在kibana查询到 2. 分析 推荐日志的整个收集流程如下: flowchart LR 线上机器日志 -->