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

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 一个空格引发的“救火之旅”:记一次SOFA RPC的排查过程

背景

说明:即使你对SOFA RPC的技术不熟悉,也能从这篇文章中体会到排查问题的实用技巧,希望对大家有所启发。
最近某银行在测试环境发布了一套SOFA RPC应用,包括SOFA RPC Service和SOFA RPC Reference。但是他们业务在调用SOFA RPC服务时出错了。
由于问题复杂性高,前线查了一天也没有头绪。
由于客户的项目时间紧张,所以这个问题升级到我这里处理。救火之旅就此开始。

SOFA RPC原理

在进入正题之前,我们简单介绍一下SOFA RPC的原理,如图1:SOFA RPC原理图所示。
图1:SOFA RPC原理图.png

图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调用错误.png

图2:RPC调用错误

同时,客户还提到,同一套代码在测试环境中调用失败,但是在开发环境中调用成功。
代码中,有application-test.properties和application-dev.properties配置文件,分别对应着测试环境和开发环境,如图3:配置文件所示。
注意:SOFA的应用支持按照环境自动加载对应的配置文件(测试环境加载-test配置文件,开发环境加载-dev配置文件),对于该功能的详情,请点击这里
图3:配置文件.png

图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:测试环境配置文件.png

图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日志.png

图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报错.png

图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:代码逻辑.png

图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:招式总结.png

图8:招式总结

作者:李聪

阿里云智能GTS-SRE团队金融线技术服务经理

曾就职于微软企业客户服务部门,擅长云计算、联盟认证、域认证、证书认证等。现在就职于阿里云智能 SRE 金融线技术服务经理团队,主要负责金融线客户的中间件(SOFA、RocketMQ、EDAS)解决方案、开发咨询等工作。

我们是阿里云智能全球技术服务-SRE团队,我们致力成为一个以技术为基础、面向服务、保障业务系统高可用的工程师团队;提供专业、体系化的SRE服务,帮助广大客户更好地使用云、基于云构建更加稳定可靠的业务系统,提升业务稳定性。我们期望能够分享更多帮助企业客户上云、用好云,让客户云上业务运行更加稳定可靠的技术,您可用钉钉扫描下方二维码,加入阿里云SRE技术学院钉钉圈子,和更多云上人交流关于云平台的那些事。

image.png

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
相关文章
|
6月前
|
负载均衡 Dubbo Java
Dubbo 3.x:探索阿里巴巴的开源RPC框架新技术
随着微服务架构的兴起,远程过程调用(RPC)框架成为了关键组件。Dubbo,作为阿里巴巴的开源RPC框架,已经演进到了3.x版本,带来了许多新特性和技术改进。本文将探讨Dubbo 3.x中的一些最新技术,包括服务注册与发现、负载均衡、服务治理等,并通过代码示例展示其使用方式。
349 9
|
6月前
|
JSON 负载均衡 网络协议
Rpc编程系列文章第二篇:RPC框架设计目标
Rpc编程系列文章第二篇:RPC框架设计目标
|
6月前
|
设计模式 负载均衡 网络协议
【分布式技术专题】「分布式技术架构」实践见真知,手把手教你如何实现一个属于自己的RPC框架(架构技术引导篇)
【分布式技术专题】「分布式技术架构」实践见真知,手把手教你如何实现一个属于自己的RPC框架(架构技术引导篇)
256 0
|
11天前
|
自然语言处理 负载均衡 API
gRPC 一种现代、开源、高性能的远程过程调用 (RPC) 可以在任何地方运行的框架
gRPC 是一种现代开源高性能远程过程调用(RPC)框架,支持多种编程语言,可在任何环境中运行。它通过高效的连接方式,支持负载平衡、跟踪、健康检查和身份验证,适用于微服务架构、移动设备和浏览器客户端连接后端服务等场景。gRPC 使用 Protocol Buffers 作为接口定义语言,支持四种服务方法:一元 RPC、服务器流式处理、客户端流式处理和双向流式处理。
|
6月前
|
Dubbo Java 应用服务中间件
Rpc编程系列文章第三篇:Hessian RPC一个老的RPC框架
Rpc编程系列文章第三篇:Hessian RPC一个老的RPC框架
|
3月前
|
Dubbo 网络协议 Java
RPC框架:一文带你搞懂RPC
这篇文章全面介绍了RPC(远程过程调用)的概念、原理和应用场景,解释了RPC如何工作以及为什么在分布式系统中广泛使用,并探讨了几种常用的RPC框架如Thrift、gRPC、Dubbo和Spring Cloud,同时详细阐述了RPC调用流程和实现透明化远程服务调用的关键技术,包括动态代理和消息的编码解码过程。
RPC框架:一文带你搞懂RPC
|
2月前
|
XML 负载均衡 监控
分布式-dubbo-简易版的RPC框架
分布式-dubbo-简易版的RPC框架
|
3月前
|
XML 存储 JSON
(十二)探索高性能通信与RPC框架基石:Json、ProtoBuf、Hessian序列化详解
如今这个分布式风靡的时代,网络通信技术,是每位技术人员必须掌握的技能,因为无论是哪种分布式技术,都离不开心跳、选举、节点感知、数据同步……等机制,而究其根本,这些技术的本质都是网络间的数据交互。正因如此,想要构建一个高性能的分布式组件/系统,不得不思考一个问题:怎么才能让数据传输的速度更快?
|
5月前
|
存储 缓存 Linux
【实战指南】嵌入式RPC框架设计实践:六大核心类构建高效RPC框架
在先前的文章基础上,本文讨论如何通过分层封装提升一个针对嵌入式Linux的RPC框架的易用性。设计包括自动服务注册、高性能通信、泛型序列化和简洁API。框架分为6个关键类:BindingHub、SharedRingBuffer、Parcel、Binder、IBinder和BindInterface。BindingHub负责服务注册,SharedRingBuffer实现高效数据传输,Parcel处理序列化,而Binder和IBinder分别用于服务端和客户端交互。BindInterface提供简单的初始化接口,简化应用集成。测试案例展示了客户端和服务端的交互,验证了RPC功能的有效性。
392 7
|
4月前
|
分布式计算 负载均衡 数据安全/隐私保护
什么是RPC?有哪些RPC框架?
RPC(Remote Procedure Call,远程过程调用)是一种允许运行在一台计算机上的程序调用另一台计算机上子程序的技术。这种技术屏蔽了底层的网络通信细节,使得程序间的远程通信如同本地调用一样简单。RPC机制使得开发者能够构建分布式计算系统,其中不同的组件可以分布在不同的计算机上,但它们之间可以像在同一台机器上一样相互调用。
149 8
下一篇
无影云桌面