写点什么

一个空格引发的“救火之旅” - 记一次 SOFA RPC 的排查过程

发布于: 2020 年 08 月 31 日

背景

说明:即使你对 SOFA RPC 的技术不熟悉,也能从这篇文章中体会到排查问题的实用技巧,希望对大家有所启发。



最近某银行在测试环境发布了一套 SOFA RPC 应用,包括 SOFA RPC Service 和 SOFA RPC Reference。但是他们业务在调用 SOFA RPC 服务时出错了。



这个问题很诡异。诡异到一线和客户查了一天没有查出来。



由于客户的项目时间紧张,所以这个问题升级到我这里处理。救火之旅就此开始。



SOFA RPC 原理

在进入正题之前,我们简单的介绍一下 SOFA RPC 的原理。



image.png



  • 当 SOFA RPC Service 的应用启动的时候,他们是通过 ACVIP (公有云里叫 AntVIP ) 获取到 SOFA Registry (注册中心) 的地址的。ACVIP 的地址需要填入 RPC Service 和 RPC Reference 的代码配置文件里。RPC Service 会将该应用的 RPC 服务注册到 SOFA Registry 上。

  • 当引用这个服务的 SOFA RPC Reference 应用启动时,会从 SOFA Registry 订阅到相应服务的元数据信息 ( SOFA RPC Service 的 IP,端口等信息)。SOFA Registry 收到订阅请求后,会将发布方的元数据实时推送给 SOFA RPC Reference。

  • 当 SOFA RPC Reference 拿到元数据后,就可以从中获得服务地址,并发起调用。如图中 Reference 指向 Service。



问题现象

让我们回顾一下问题的现象。SOFA RPC Reference 应用在尝试调用 SOFA RPC Service 的时候,报 “Cannot get service address of service XXXXXXXXX” 的错误。



image.png



同时,客户还提到,同一套代码在测试环境中调用失败,但是在开发环境中调用成功。

代码中,有 application-test.properties 和 application-dev.properties 配置文件,分别对应着测试环境和开发环境。

注意:SOFA 的应用支持按照环境自动加载对应的配置文件(测试环境加载-test配置文件,开发环境加载-dev配置文件),对于该功能的详情,请点击这里



image.png



排查过程

招式一、根据产品原理缩小问题范围

在排查产品问题时,最有效的方式是从产品的原理的角度将问题范围缩小。

根据错误消息,我们知道 RPC Reference 没有获得服务的地址。那么没有获得服务的地址可能的原因有哪些?从上面的原理图,我们可以看到可能的原因有以下几种:

  • RPC Reference 没有连接上 SOFA Registry

  • RPC Reference 没有从 ACVIP 处获得 SOFA Registry 的地址

  • RPC Reference 跟 SOFA Registry 之间的 9600 端口异常

  • SOFA Registry 异常

  • RPC Service 服务没有发布成功

  • RPC Service 跟 SOFA Registry 之间的 9600 端口异常

  • RPC Service 没有从 ACVIP 处获得 SOFA Registry 的地址

  • RPC Service 应用启动异常



根据原理,继续缩小范围的结果如下。

  • RPC Reference 没有连接上 SOFA Registry。排查结果 - 排除❎。

  • RPC Reference 没有从 ACVIP 处获得 SOFA Registry 的地址。排查结果 - 排除❎。

  • 使用 "netstat -an | grep 9600" 发现该 RPC Reference 与 SOFA Registry 之间有 9600 端口的长连接,所以排除该问题。

  • RPC Reference 跟 SOFA Registry 之间的 9600 端口异常。排查结果 - 排除❎。

  • 根据 netstat 的输出,发现长连接状态为 Established,所以排除该问题。

  • SOFA Registry 异常。排查结果 - 排除❎。

  • 测试环境和开发环境是共用一套 SOFA Registry 的,但是开发环境可以正常工作,所以 SOFA Registry 没有问题。

  • RPC Service 服务没有发布成功。

  • RPC Service 跟 SOFA Registry 之间的 9600 端口异常。排查结果 - 异常✅

  • 使用 "netstat -an | grep 9600" 发现该 RPC Service 与 SOFA Registry 之间没有 9600 端口的长连接!

  • RPC Service 没有从 ACVIP 处获得 SOFA Registry 的地址。排查结果 - 异常✅

  • 经过排查,ACVIP 的日志文件 (/home/admin/logs/acvip-java-client)没有生成。这说明 ACVIP 框架没有加载。

  • RPC Service 应用启动异常。排查结果 - 排除❎。

  • 检查应用启动日志,/home/admin/logs/stderr.log 为空。



到了这一步,已经定位到 RPC Service 应用的 ACVIP 框架没有被加载,所以导致后续流程无法继续。这时候,我们怀疑是应用代码的问题。可是从 /home/admin/logs/stderr.log 和 /home/admin/logs/stdout.log 中,我们没有发现异常,应用也能够正常启动,只是不能加载 ACVIP 框架。



招式二、引入第三方缩小问题范围

承接上文,排查到这里就卡住了。

客户觉得是 SOFA RPC 框架的问题,但是我们排查下来猜测是客户代码配置的问题。可是客户再次强调开发环境和测试环境用的是同一套代码,开发环境是好的。



这时候,为了让客户和我们站在同一个排查方向上(对于这种开发问题,要是客户和我们不在一个排查方向上,会严重影响问题排查效率),相信是代码的问题,需要引入第三方从侧面证明是代码问题。



我们将自己写的一个最简单的 SOFA RPC 的 Demo 发给客户,然后使用测试环境的配置运行。该 Demo 能够正常运行。这说明肯定还是客户代码的问题。这时候,客户和我们站在统一战线。客户也在帮忙检查代码是否还有为检查的遗漏点。



可惜,客户还是没能看出代码的问题。



招式三、对比大法找突破口

承接上文,排查过程再次卡住。



于是,我们再重头梳理一遍问题,我们知道开发环境和测试环境用的是同一套代码,只是配置文件不一样。那么我们在同一台 RPC provider 的机器上,部署开发环境的配置是否可以运行成功?这时,我们把 application-dev.properties 文件删除,只保留 application-test.properties,同时只更改以下三个配置属性。



image.png



更改了配置之后,配置文件的内容是开发环境的对应的值,运行成功。重新修改回测试环境的配置,运行失败。



由于是在同一台机器上运行,可以排除掉很多异构因素。所以可以开始进行日志对比大法。



我们将这两次测试的所有日志都收集上来。

运行成功的应用因为加载了 ACVIP,所以生成了 /home/admin/logs/acvip-java-client 目录以及文件。

运行失败的应用因为没有加载 ACVIP,所以没有生成 /home/admin/logs/acvip-java-client 目录。



通过对比 stdout.log,也没有发现什么不同。

但是我们从运行成功的应用的 /home/admin/logs/acvip-java-client 目录下面发现 STARTUP.log 的日志,其记录了 ACVIP 初始化过程。从这个日志我们能看到 ACVIP 初始化的时间点。



招式四、时间回溯,逼近真相

承接上文,我们拿到 ACVIP 初始化的时间点:2020-07-01T18:35:12,086。



image.png



拿到 ACVIP 初始化的时间点,有什么用呢?



当信息太碎片化的时候,我们往往发现不了这些信息的价值。但是当我们找到一根主线将这些信息串联起来,那我们很可能得到一个价值连城的故事。



现在,就是我们用主线将碎片化的信息串联起来的时候了。而主线就是时间点。



因为我们知道了 ACVIP 的初始化的时间点,那么我们只需要关心这个时间点前发生的故事。

回到 stdout.log,参考这个时间点,我们发现在那个时间点 SOFA 框架正在初始化 DRM (动态配置组件),但是有报错。2020-07-01 18:35:12:at com.alipay.drm.client.remoting.client.ClientManager.<init>



image.png



这个错误在正常运行和非正常运行的测试场景都有,而且 callstack 一模一样。所以这个错误本身并不重要。

重要的是,发生这个错误的时候,SOFA 框架正在初始化 DRM 组件。



接着,我们将重心转移到 DRM 组件的初始化:查看运行正常的 /home/admin/logs/drm-boot.log 日志。我们发现这一条 “Query zdrmdata url pool from antvip”,这说明 DRM 组件从 ACVIP 那边获得了 DRM 服务端的 IP。同时,我们注意到 DRM 初始化的时间是 2020-07-01 18:35:11,947,这比 ACVIP 的初始化时间晚!这说明是 DRM 触发了 ACVIP 初始化。

2020-07-01 18:35:11,947 INFO  Start building distributed resource ...

...

2020-07-01 18:35:11,991 INFO  Init access key from system param: middleWarexxxx

2020-07-01 18:35:11,991 INFO  Init secretKey key from system param.

2020-07-01 18:35:11,991 INFO  Init instance id name from system param: xxxInstanceID

...

2020-07-01 18:35:13,205 INFO  Query zdrmdata url pool from antvip:



接下来,让我们再来看看非正常运行的应用的 DRM 日志。该日志有报错:“ERROR Query confreg http url failed!”

2020-07-01 19:38:44,511 INFO  Start building distributed resource ...

...

2020-07-01 19:38:44,557 INFO  Init access key from system param: middleWarexxxx

2020-07-01 19:38:44,557 INFO  Init secretKey key from system param.

2020-07-01 19:38:44,605 ERROR Query confreg http url failed!



假如我们盯着这个错误看,可能被误导到一个错误的方向。

通过对比两者的 DRM 日志,我们发现正常运行的应用的 DRM 日志会 “Init instance id name from system”,但是非正常运行的应用的 DRM 日志却没有。而 instanceID 是 acvip 寻址所必须的。



招式五、研究代码逻辑,重现问题

从 DRM 日志中,我们发现了 DRM 初始化逻辑轨迹的不同。

而日志内容是通过代码里的 Logger 设置的。所以我们可以通过日志内容去代码里看相应的逻辑(这是客户端的代码,客户和我们都可以查看)。



我们通过在代码里面搜索 “Init secretKey key from system param”,发现在加载 instance id 之前,代码里有一个判断。这个判断是,假如 antCloud 为 True,才会去加载 instance id。

这个 antCloud 为不为 True 取决于配置文件中 com.alipay.env 的值是否为 shared



image.png



我们的代码里面使用的是 equalsIgnoreCase 在做对比,但是代码里面没有考虑该值有空格的情况(没有trim),所以当配置文件中 com.alipay.env 的值是 shared+空格,而不是 shared, 那么就无法触发 ACVIP 初始化了。

 

为了验证我们的想法,我们重新检查了 stdout.log。

非正常运行的应用是这样的:

Not find key com.alipay.env in Java -D argument, put value shared  into System(shared后多了一个空格)

 

正常运行的应用是这样的:

Not find key com.alipay.env in Java -D argument, put value shared into System



直接从配置文件的截图是看不出来是否 shared 后面有没有空格的。



我们马上在本地做了一个实验,果然可以重现问题。



解决方案

客户将 application-test.properties 里面的 shared 后面的空格去掉后,问题解决。



总结

最后,我将这几个招式总结到下面的流程图中。





发布于: 2020 年 08 月 31 日阅读数: 873
用户头像

还未添加个人签名 2020.08.07 加入

还未添加个人简介

评论 (1 条评论)

发布
用户头像
这应该算框架bug吧
2020 年 09 月 04 日 13:56
回复
没有更多了
一个空格引发的“救火之旅” - 记一次 SOFA RPC 的排查过程