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

曲池 阿里云开发者 2023-10-11 08:31 发表于浙江

阿里妹导读

本文只是总结下线上问题的排查过程，不讲方法论，没有大道理，行文会较为随意，注重的是排查思路，希望对同学们日常研发工作有所帮助~

问题

前天同学反馈， 搜索业务的核心应用 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 插件的脚本：