背景
说明：即使你对SOFA RPC的技术不熟悉，也能从这篇文章中体会到排查问题的实用技巧，希望对大家有所启发。
最近某银行在测试环境发布了一套SOFA RPC应用，包括SOFA RPC Service和SOFA RPC Reference。但是他们业务在调用SOFA RPC服务时出错了。
由于问题复杂性高，前线查了一天也没有头绪。
由于客户的项目时间紧张，所以这个问题升级到我这里处理。救火之旅就此开始。
SOFA RPC原理
在进入正题之前，我们简单介绍一下SOFA RPC的原理，如图1：SOFA RPC原理图所示。
图1：SOFA RPC原理图
- 当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”的错误，如图2：RPC调用错误所示。
图2：RPC调用错误
同时，客户还提到，同一套代码在测试环境中调用失败，但是在开发环境中调用成功。
代码中，有application-test.properties和application-dev.properties配置文件，分别对应着测试环境和开发环境，如图3：配置文件所示。
注意：SOFA的应用支持按照环境自动加载对应的配置文件（测试环境加载-test配置文件，开发环境加载-dev配置文件），对于该功能的详情，请点击这里。
图3：配置文件
排查过程
招式一、根据产品原理缩小问题范围
在排查产品问题时，最有效的方式是从产品的原理的角度将问题范围缩小。
根据错误消息，我们知道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.p所示roperties文件删除，只保留application-test.properties，同时只更改以下三个配置属性，如图4：测试环境配置文件所示。
图4：测试环境配置文件
更改了配置之后，配置文件的内容是开发环境的对应的值，运行成功。重新修改回测试环境的配置，运行失败。
由于是在同一台机器上运行，可以排除掉很多异构因素。所以可以开始进行日志对比大法。
我们将这两次测试的所有日志都收集上来。运行成功的应用因为加载了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，如图5：ACVIP Startup日志所示。
图5：ACVIP Startup日志
拿到ACVIP初始化的时间点，有什么用呢？
当信息太碎片化的时候，我们往往发现不了这些信息的价值。但是当我们找到一根主线将这些信息串联起来，那我们很可能得到一个价值连城的故事。
现在，就是我们用主线将碎片化的信息串联起来的时候了。而主线就是时间点。
因为我们知道了ACVIP的初始化的时间点，那么我们只需要关心这个时间点前发生的故事。
回到stdout.log，参考这个时间点，我们发现在那个时间点SOFA框架正在初始化DRM（动态配置组件），但是有报错。2020-07-01 18:35:12：at com.alipay.drm.client.remoting.client.ClientManager.。如图6：DRM报错所示。
图6：DRM报错
这个错误在正常运行和非正常运行的测试场景都有，而且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，如图7：代码逻辑所示。
这个antCloud为不为True取决于配置文件中com.alipay.env的值是否为shared。
图7：代码逻辑
我们的代码里面使用的是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后面的空格去掉后，问题解决。
总结
最后，我将这几个招式总结到下面的流程图中，希望对读者能够有所帮助和启发，如图8：招式总结所示。
图8：招式总结
作者：李聪阿里云智能GTS-SRE团队金融线技术服务经理
曾就职于微软企业客户服务部门，擅长云计算、联盟认证、域认证、证书认证等。现在就职于阿里云智能 SRE 金融线技术服务经理团队，主要负责金融线客户的中间件（SOFA、RocketMQ、EDAS）解决方案、开发咨询等工作。
我们是阿里云智能全球技术服务-SRE团队，我们致力成为一个以技术为基础、面向服务、保障业务系统高可用的工程师团队；提供专业、体系化的SRE服务，帮助广大客户更好地使用云、基于云构建更加稳定可靠的业务系统，提升业务稳定性。我们期望能够分享更多帮助企业客户上云、用好云，让客户云上业务运行更加稳定可靠的技术，您可用钉钉扫描下方二维码，加入阿里云SRE技术学院钉钉圈子，和更多云上人交流关于云平台的那些事。
