预发部署时机器总是重启两次的“简单”排查

原创
2023/10/19 10:02
阅读数 29

问题

前天同学反馈, 搜索业务的核心应用 magellan 在预发环境部署时总是重启两次,刚部署好,开始联调,突然又重启了,也导致老是被人抱怨搜索环境不稳定。

第一反应是,大概率是应用第一次启动失败了吧?总不可能是 Aone(阿里内部 CI/CD 系统)调度两次吧。结果:

这,的确没有遇到过,只能表示:

这么神奇的现象是偶尔还是必现呢?额,竟然是必现。。。。。。

既然必现,那还是能排查的、好排查的,试试吧~

查看日志,确认到底部署了几次

 

 

开发同学发来了部署日志截图,如上面几张图所示:

  • 01:41 时停止应用,然后销毁容器,创新新容器
  • 01:43 时开始启动应用,启动成功
  • 01:50 时又开始停止应用、重启应用了,但此时并没有新的部署记录。

当然上面的图里看的不太清晰,我们还是做下简单匹配:匹配下停止和启动时的日志(grep -E),同时向上向下各显示一行日志(-C 1),主要是为了把时间打印出来。

cat magellan_deploy.log  |grep -E "INFO: magellan try to stop...|INFO: magellan try to start..." -C 1

机器 1 的启动日志

机器 2 的启动日志

当然上面这命令,也只是此刻我梳理整体过程时才想起来(所以跟开发同学提供的截图不太一致),排查问题时也就大概看看日志。不过通过上面的图,我倒是又发现了一个之前遗漏的点:两个机器的第一次启动时间不一样(分 2 批启动,机器 1 是第一批启动,机器 2 是第二批启动),但是他们第二次的重启时间是一样的,都是 21:00:02 ,说明是同一时刻被调度的,这也印证了后面的结论,不过,目前我们暂且忽略该信息。无论是从上面事前开发同学截的图,还是从我事后截的图,都可以看出:应用的确是重启了两次,第一次应该是 Aone 调度的,但第二次不知道是谁调度的。

手动重启应用会不会也有这个问题呢?

手动重启了下,启动成功后,应用就上线了,等了 2、3 分钟,应用没有再次重启。。。额,难道只有在 Aone 部署的时候才会?看了最近一周的部署日志,的确基本都是重启两次。

有没有定时任务

额,没有。

没啥思路,看看有没有有用的报错信息吧

仔细翻了翻,应用启动日志中并没有什么特别的、新的报错,部署日志倒是有一个警告信息:Pandoraboot 可以类比于 Springboot

记得之前看过一些文章,说这个错误有可能会影响 JDK 版本的判断(主要是由于部分 JDK 版本判断的脚本不太健壮)。另外,我刚才手动部署时,好像也有一行报错,估计是由这个错误引起的,赶紧重新执行下 sh stop.sh(阿里内部手动下线某台机器的命令):

提示 update_setenv.sh(阿里内部应用启动脚本之一) 的 21 行有问题,看下代码:

梳理了逻辑,大概是执行 java -version ,获取版本号,如果大于等于 JDK8,则替换一些 JVM 参数。估计是当年升级 JDK8 时的遗留产物。为啥会报错呢?登录机器执行了下命令:

额,执行该命令时 OpenJDK 报了 Warning 信息,而且报错信息在 version 那行之前,这样第一行就匹配不到真正的版本号 8 了,按照上面代码的执行逻辑,JAVA_VERSION_MAJOR 会取到 "Server" 中的第一个"e",取到了一个字符串,导致下面和数字 8 比较时报错。那这里执行报错会带来什么影响呢?下面的替换逻辑就不会执行了,最终 JVM 的启动参数设置不合理,可能导致 JVM 被杀掉了?那看看应用现在的启动参数设置吧:

额,启动参数已经改成 JDK8 之后的了,所以上面的替换逻辑不执行也不会影响最终的启动参数。虽然不影响启动参数,但部署日志里,有这么多的这行错误日志,而且 JDK 版本获取错误估计也会引起一些不可知的问题。先修复掉试试~

修复 JDK 版本判断错误的逻辑

看了下这个 update_setenv.sh 的代码,发现已经没用了,而且判断 JDK 版本的代码逻辑也写的很有问题,可以直接删除。拉变更,删除,部署预发。

部署成功,应用开始启动后,登录机器观察部署日志:应用部署正常,无 JDK warning 信息,等了几分钟也没有重新部署。好像是解决了。但为什么解决了呢?不科学呀。照理说,这个版本判断和两次重启关系不是很大呀。算了,先不纠结,赶紧反馈给开发同学。

 
 

为了能将这份喜悦第一时间传递给开发,我还特意使用了快速通道——DING,结果很快就打脸了。

是运行时问题?

赶紧上机器看了下日志,发现:这个机器在 20:54 分的时候已经启动成功了,运行了 5 分钟后才被重启(我只等了 3、4 分钟)。这就说明:不是应用启动时的问题,而是运行时问题,怪不着我之前老是观察不到,原来是启动后不确定的时间内会被重启。嘴上跟开发同学说,我再努力找找,但其实内心没有一点思路。。。找 Aone 同学问问吧,万一是 Aone 重复调度了呢?

咨询 Aone 同学是否存在重复调度的可能性

Aone(阿里内部 CI/CD 系统) 右下角咨询了研发小蜜,很快就有了答复。

 

不过,同学回复的答案跟我的问题并不相关,应该是理解错我的意思了。他估计以为我要暂停容器、排查问题,可以理解,问题是比较诡异。提问前,我还仔细阅读了下 Aone 的历史提问记录,发现里面并没有类似的问题,大概率不是 Aone 的问题。还是先再试试其他方法,实在不行的话,再找 Aone 同学确认是否有重复调度。

还能从什么角度进行排查呢?有点排查不下去了。想起来了,据开发同学说,只有预发机器有,线上机器没有这个问题,那就对比下线上和预发的机器吧。

全方位对比线上和预发机器

对比应用部署日志:无异常对比应用启动日志:无异常对比 JVM 参数:有点不一样,如下,第一张是线上机器的参数,第二张是预发机器的参数

 

区别有几个地方:

  • 使用的 java 路径不一样:线上是/opt/taobao/install/ajdk-8_2_4-b52/bin/java,预发是 /opt/taobao/java/bin/java
  • 预发环境的机器开启了 Debug 端口: -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=8000
  • 预发环境的机器挂载了一个 Java Agent: -javaagent:/home/admin/remote-debug/libs/remote-debug-agent.jar

Java 路径的:登录机器看了下,两个路径做了软链接,本质是一样的(预发和线上有区别是由于我在预发环境删除了 update_setenv.sh 导致的):

预发机器的 Debug 端口开启:估计是有同学在预发 Debug,这也不会有啥问题。预发环境的机器挂载 Java Agent:这个一般也是常规操作了,比如用来做启动耗时分析的 start-ops,用来做代码染色的 rbc 等,都是只挂载预发,防止 Agent 影响线上真实用户,就是不知道这个 remote-debug 是用来干啥的。对比了半天,也没有任何头绪。。。总不能是这个 Agent 引起的吧?Agent 一般也不会,并且也不能重启应用的呀。算了,先看看这个 Agent 是干啥的

看看 remote-debug Agent 是干啥的

既然是 Java Agent,而应用代码里又没有 Agent 部署的相关代码,那么这个 Agent 应该是通过运维插件下发的,这样应用才是无感的。先在 staragent 插件市场(阿里内部运维容器插件市场)里搜索看看是干啥的:

试了 remote debug、remote debug agent 等一系列关键词,发现都搜索不到,奇怪,难道插件不叫这个名字??那就网上搜索下,信息都没啥用,全是远程 debug 的,没办法,谁让这个插件叫这个名字呢。

语雀搜索,内网公开,排在前面的也没啥用(其实这里,我忘记在外网搜索了,其实 github 是可以搜索到一些相关信息的)。代码搜索(阿里内部代码仓库搜索平台)下吧,不过这次我为了更精确的匹配使用了关键词“remote-debug-agent”,有戏!

路径完全一致,QA 出品,放在 euler-service 的仓库里,难道插件名字叫 euler?这脚本里好像执行了 appctl.sh restart 重启!赶紧再次在插件市场搜索了下,果然有!

登录预发机器看看 staragent 的插件目录,没错,就是你,原来叫 euler !

进去目录看看实际的脚本,果然与代码搜索到的基本一致:

看看逻辑:

  • 在预发、测试、日常、项目环境下,如果 remote-debug-agent.jar 不存在,就从 oss 下载到 /home/admin 目录下
  • 如果 remote-debug-agent 已经被挂载了,就啥也不干
  • 如果 remote-debug-agent 没有被挂载,就修改 setenv.sh 脚本里的 JVM 参数,追加 Agent 参数,然后重启应用

难道第二次的重启是为了挂载 remote-debug-agent 这个 Agent?

观察应用的两次重启

第一次重启后,赶紧观察:

等待第二次重启后,观察:

果然,第二次多了 -javaagent:/home/admin/remote-debug/libs/remote-debug-agent.jar!八九不离十了,应该就是这个 euler 运维插件引起的了。

找插件负责人确认

找 euler 插件的维护同学确认了下是否存在这个逻辑:

哈哈,终于找到了,测试同学表示:你是怎么查出来的,这个很难查到是这个插件引起的。我说,是难,我都打算放弃了。赶紧约测试同学当面沟通了下,确认了他们的诉求:他们期望,在不需要开发同学修改代码的前提下,应用预发部署的时候就可以挂载这个 Java Agent,辅助他们采集一些数据。但他们研究了之后,发现无法做到在应用启动前就修改启动脚本里的 JVM 参数,所以只好采取了重启的方式。每 10 分钟左右调度一次,所以才会出现启动 5 分钟后突然重启的现象。他们以为应用启动一般比较快,对开发的影响较小。其实,正常情况下影响的确很小,但现在的应用一般都需要 3 分钟才能完成重启,同时 magellan 又是高频发布应用(1 个月预发部署 150 次左右),开发人员多,需求多,所以很容易被开发同学发现:


知道了问题,怎么解决呢?简单,近期我正好在和架构组同学在一起开发、推广另一款插件,我们的插件在第一次重启的时候就挂载上了,不用二次重启,赶紧拉上测试同学和架构组同学一起沟通下修改方案(本文重点不在于怎么修复,所以就不放出修复方案相关的内容了)。确定方案后,测试同学就赶紧回去改代码了,说是太不好意思了,今天肯定优化好。

其实,这有啥不好意思的,大家不都是互相伤害来伤害去的嘛,如果实在不好意思,一杯咖啡的事。
最后

  • 先给 magellan 预发环境摘除了插件,保证开发体验,等插件逻辑修复好了再重新挂载

  • 在设计上,运维容器和主容器在同一个 Pod 内,共享磁盘,运维容器的确有权限操作主容器里的进程,那么在架构上要如何防范呢?我还没有答案,不知各位是否有,有的话,请留言告知。
  • 如果非要说本次排查过程有什么深刻体会的话,那就是“不要放过任何一个可疑的地方”!

补:如果代码搜索没找到,是否还有其他方法

昨晚在回家的路上,在想一个问题,如果在使用代码搜索并没有搜到“remote-debug-agent”相关的任何信息,我是否还有其他方法?想了一会,发现还有一个笨方法——关键字匹配,即全文搜索“ restart”关键词。虽然笨,但很有效。先在 /home/admin 目录下搜索,没有结果就在 /home 目录下,还没有结果就在根目录下搜索。为什么这个方法可以呢?因为看部署日志,一定是执行了应用启动脚本 appctrl.sh 里的 restart 命令,所以一定含有“appctrl.sh restart” 或“ restart”关键字。

额,搜索的文件太多了,执行有点慢,被我终止了,那能不能快点?既然要执行这个命令,一般情况下应该是个脚本文件,可以优先在 *.sh 脚本文件中查找。

/home/admin 目录下,结果较少。既然扩大搜索范围,在 /home 目录下有 57 条记录,里面就有 euler-service 插件的脚本:

作者|曲池

点击立即免费试用云产品 开启云上实践之旅!

原文链接

本文为阿里云原创内容,未经允许不得转载。

展开阅读全文
加载中
点击引领话题📣 发布并加入讨论🔥
打赏
0 评论
0 收藏
0
分享
返回顶部
顶部