蚂蚁技术团队：传输币种被篡改问题排查

640?wx_fmt=gif

内容来源：本文转载自战略合作伙伴 金融级分布式架构 （ID:Antfin_SOFA）

责编 | 菱酒

第 707 篇技术好文：7772字 | 18分钟阅读

640?wx_fmt=jpeg

导读

本文将分享一个在 RPC 调用过程中，传输币种信息被篡改问题的排查过程，借此跟大家分享一些排查问题的思路和经验。

扫描二维码关注公众号，回复： 1735808 查看本文章

本文这个问题只能在预发环境复现，用到的排查工具为蚂蚁内部研发的工具，但大家也可以使用其他类似的工具，比如 greys 等来做替代。以下文章中用到的工具将称为 greys。如果线下遇到疑难问题，能够复现的，也可以直接远程 debug 来排查。本文主要还是想分享以下问题的排查思路，不局限于某些工具的使用。

问题描述

_____

首先简要介绍下，出现问题的系统链路可以简化为：

Client 直接调用 Server，可以看到 Server 返回了某个对象币种是 CNY，但是 Client 从自己的调用结果处看到的是 USD。

640?wx_fmt=png

业务同学反馈是线上的问题，应用运行一段时间后出现，一段时间后又会恢复正常，线下未能复现。

在 Client 机器上，通过 curl 简单测试这个接口，发现返回结果确实是 USD，不符合预期。debug 下游系统 Server 时返回的是 CNY，但是在 Client 这个调用端里面拿到的却是 USD。当时通过远程 debug 和 greys 都看到了这个情况，以下是直接观察 Server 的实现类返回结果的命令：

watch com.alipay.server.QueryFacadeImpl convert "{params,returnObj}" -x 4

复现步骤

_____

这种问题无法通过现有的中间件或者业务日志进行排查，需要有可以复现的环境。经过业务同学的尝试和观察，发现系统运行一段时间后，这个问题会复现。方便起见，可以直接通过 xfire (历史兼容的调用方式)触发以下操作复现：

curl -v -d '
<Envelope xmlns="http://schemas.xmlsoap.org/soap/envelope/">;
<Body>
<queryList xmlns="http://quotation.api.facade.service.common.client.alipay.com">;
<in0>
<userId xmlns="http://request.facade.service.common.client.alipay.com">用户</userId>;
</in0>
</queryList>
</Body>
</Envelope>' -H "Content-Type: text/xml;charset=UTF-8 " -H "SOAPAction:" [http://127.0.0.1:8080/client/queryFacade](http://127.0.0.1:8080/client/queryFacade) | xmllint --format - | sed 's/ xmlns=".*"//g'

排查

_____

排除业务自己的操作

跟相关同学确认 Server 目标系统本周未发布，但 Client 有变更发布。

对 Client 和 Server 的代码都进行了阅读，可以非常明确地确认，Client 没有任何转换结果的操作，而 Server 线上一直正常。且从现象看到 Server 返回的结果确实正确，而且 Server 的这段返回代码通过 Git 记录可以看到，已经上线运行两年，基本排除 Server 端代码的问题。

同时，jad 反编译看了一下运行中的类代码：

640?wx_fmt=png

可以看到关键位置代码确实没有任何转换操作，直接调用了 Server 的接口，然后就返回了结果。这个原因可以排除了。

确认是否有业务的拦截器干扰

再确认一下拦截器的干扰。因为拦截器有时候写的非常泛化，比如很多开发同学会配置一个 *Facade 用来拦截所有的对外提供的服务，所以还是要确认下是否有拦截器的特殊操作。

Client 端执行下以命令：

stack com.alipay.client.QueryFacadeClientImpl queryList

可以看到通过 WS 请求的调用栈没什么异常，可以排除这个影响：

$ stack com.alipay.client.QueryFacadeClientImpl queryList
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 81 ms.
ts=2017-11-22 13:26:39;thread_name=xxxThreadPool.1--22;id=ac;is_daemon=false;priority=5;TCCL=com.alipay.cloudengine.extensions.equinox.KernelAceClassLoader@48e5707f
@sun.reflect.GeneratedMethodAccessor209.invoke()
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
以下省略.

排查是否是故障注入

蚂蚁中间件在框架中做了埋点，允许在授权的情况下进行一些故障的注入模拟，因此也进行了排查。

通过检查服务端和客户端的 /logs/appName/sla*.log 相关的日志，可以确认并没有故障故障相关的操作，相关同学从故障注入管控台也同步进行了确认，这一项也可以排除。

排查是否PRC框架序列化本身的问题

前面看到服务端业务返回正常，那么正常处理的下一步就是服务端将业务的 response 序列化成二进制，然后传输给客户端。客户端的 RPC 再将这个二进制数据进行反序列化成 response，所以两端 debug ：

通过 greys 在客户端查看反序列化的结果信息：

watch com.alipay.remoting.rpc.protocol.RpcResponseCommand deserializeContent 'target.responseObject.appResponse' -x 4

同时在服务端看一下序列化 reponse 的信息：

watch com.alipay.remoting.rpc.protocol.RpcResponseCommand serializeContent 'target.responseObject.appResponse' -x 4

查看服务端序列化结果的时候 appResponse 是对的，注意看currency=@Currency[CNY] 这个字段：

serialVersionUID=@Long[4967706468767245519],
stockId=@String[2026],
date=@Date[2017-11-22 14:00:00,000],
price=@XXXMoney[
serialVersionUID=@Long[-4428879431422757138],
amount=@BigDecimal[656.80],
DEFAULT_CURRENCY_CODE=@String[CNY],
DEFAULT_SCALE=@Integer[4],
DEFAULT_ROUNDING_MODE=@Integer[6],
currency=@Currency[CNY],
scale=@Integer[2],
],

对比了一下客户端和服务端返回的结果：

640?wx_fmt=png

可以很清楚地看到反序列化完成时，客户端收到的结果就已经变了。注意看图中的 currency 字段。

同时说明服务端序列化是没有问题的，问题可能出在客户端反序列化，或者网络传输的过程中。

TCP抓包判断网络

由于序列化之后就是 remoting 的传输，所以需要进行抓包，来确认两端的数据传输是否有问题。

在客户端抓包命令中的 IP 是服务端 IP

sudo tcpdump -i eth0 -nnvvX 'dst host serverIp'

在服务端抓包命令中的 IP 是客户端 IP

sudo tcpdump -i eth0 -nnvvX 'dst host clientIp'

抓完包直接拷贝到本地对比 16 进制，进行 diff ：

640?wx_fmt=png

排除数据的位置问题，关键位置 TCP 包完全一致，问题再次回到序列化。

为了验证 TCP 的二进制包确实没有问题，将客户端收到的 TCP 包本地保存，然后以 byte 数组的方式读入内存：

640?wx_fmt=png

然后通过 RPC 中 Hessian 的反序列化进行操作：

/**
* Alipay.com Inc. Copyright (c) 2004-2017 All Rights Reserved.
*/
package com.alipay.demo.test;
import com.caucho.hessian.io.Hessian2Input;
import org.apache.commons.io.FileUtils;
import org.apache.log4j.Logger;
import java.io.ByteArrayInputStream;
import java.io.File;
import java.io.IOException;
import java.util.Currency;
/**
* @author bystander
* @version $Id: DecTest.java, v 0.1 2017年11月22日下午3:16 bystander Exp $
*/
public class DecTest {
private static final Logger LOGGER = Logger
.getLogger(DecTest.class.getName());
public static void main(String[] t) {
String result = "";
String lines = null;
try {
lines = FileUtils.readFileToString(new File("~/Downloads/byte.txt"));
} catch (IOException e) {
e.printStackTrace();
}
String[] arr = lines.split(",");
byte[] bytes = new byte[arr.length];
for (int i = 0; i < arr.length; i++) {
bytes[i] = Byte.parseByte(arr[i]);
}
XXXSerializerFactory serializerFactory = new XXXSerializerFactory();
ByteArrayInputStream input = new ByteArrayInputStream(
bytes);
Hessian2Input hessianInput = new Hessian2Input(input);
hessianInput.setSerializerFactory(serializerFactory);
try {
Object object = hessianInput.readObject();
System.out.println(object);
} catch (IOException e) {
e.printStackTrace();
}
}
}

结果反序列化正确，可以看到确实还是 CNY ， TCP 包传输网络无问题，客户端收到的包也没有问题

640?wx_fmt=png

再看序列化可能的错误

由于只有 Currency 有问题，所以和组内同学经过一系列讨论，反序列化时可以看下客户端 Currency 被调用的情况，直接在服务器上 debug ：

watch java.util.Currency getInstance "{params,returnObj.currencyCode}" -x 2

debug 的结果：

640?wx_fmt=png

图中每一块，上半部分是方法调用入参，下半部分是返回结果的币种信息。

这时候，意想不到的情况出现了。Currency 传进去的入参是 CNY，返回结果却是 USD(业务反馈有时候也会变成其他币种，比如这里复现的时候变成了 HKD)，问题基本定位。

然后需要阅读下 Currency 的实现，核心的一个代码段是如下的部分：

// class data: instance map
private static HashMap instances = new HashMap(7);

这个信息是存储在内部的 Map 中，怀疑被其他操作改掉了，同时重新触发了 USD 等币种的查询：

640?wx_fmt=png

发现是没有问题的，准备 dump 一下内存，看下内存中这个 Currency 内部的 Map 中都有什么值，对 dump 内存进行确认：

640?wx_fmt=png

可以看到，这个 Map 确实改变了，里面有四个值，CNY 对应的值已经是错误的了。

PS：XXX 是 Currency 中用来表示无币种的情况，是由hadoop的类初始化的，跟本问题无关。

https://en.wikipedia.org/wiki/ISO_4217
The code XXX is used to denote a "transaction" involving no currency.

排查其他序列化的影响

由于 Hessian 线上稳定运行，而且 Hessian 的反序列化方案是先 new 一个 Currency，然后反序列化完成后，通过 Currency 的 code 获取到原始的静态类，并不会被内存中原始的单例进行修改。

640?wx_fmt=png

这里 Hessian 有一个 resolve 的过程，如果发现自己本次构造的对象类型有这个 readResolve，就会调用一次，然后反序列化器继续使用原有的实例。

640?wx_fmt=png

这里 readResolve() 的作用是将返回的对象替换反序列化创建的实例，主要使用在单例的场景，在序列化和反序列化中主要用于用返回的对象代替反序列化的对象，否则的话，反序列化会导致内存中有很多单例对象。

这个单例类的改动，业务方肯定不会直接调用，因此怀疑是其他序列化方案导致的。跟系统 owner 沟通，业务确实使用了 ProtoStuff 的一个方案做缓存对象的序列化和反序列化，通过注解来生效，所以看代码时没有观察到。

跟组内同学一起看了一下 ProtoStuff 序列化的代码，构造一个单测。先描述一下这几个关键类的关系，简化之后：

XXXMoney:
currency:java.util.Currency
currencyCode:java.lang.String

类结构比较简单，XXXMoney 中有一个属性是 Currency 类型， Currency里面有一个关键属性是 currencyCode。以下是测试代码：

/**
*/
package com.alipay.demo.test;
import com.alipay.xxx.util.money.XXXMoney;
import com.alipay.client.cache.provider.CacheValueSizeOverflowException;
import com.alipay.client.cache.provider.ProtostuffSerializeHelper;
import org.apache.log4j.Logger;
import java.util.Currency;
/**
* @author bystander
* @version $Id: DecTest.java, v 0.1 2017年11月22日下午3:16 bystander Exp $
*/
public class SecTest {
private static final Logger LOGGER = Logger
.getLogger(SecTest.class.getName());
public static void main(String[] t) {
XXXMoney xxxMoney =null;
ProtostuffSerializeHelper helper = new ProtostuffSerializeHelper();
byte[] bytes;
try {
xxxMoney =new XXXMoney(11.0,Currency.getInstance("USD"));
bytes = helper.serialize(xxxMoney, XXXMoney.class);
helper.deserialize(bytes, XXXMoney.class);
System.out.println( Currency.getInstance("CNY"));
} catch (CacheValueSizeOverflowException e) {
e.printStackTrace();
}
}
}

以下是 debug 执行的结果，可以看到此时内存中已经被修改。

原因分析

_____

deserialize 的时候会调用以下代码：

/**
* 反序列化
*
* @param <T> the type parameter
* @param raw the raw
* @param cls the cls
* @return the t
*/
public <T> T deserialize(byte[] raw, Class<T> cls) {
Schema<T> schema = RuntimeSchema.getSchema(cls);
T val = schema.newMessage();
ProtobufIOUtil.mergeFrom(raw, val, schema);
return val;
}

这段代码的 schema.newMessage() 会调用类的构造函数，此时会调用到 XXXMoney 的无参构造函数，默认是 CNY，内存中此时会生成了一个 CNY 的 Currency 单例，并且此时 XXXMoney 的 currency 字段已经有这个值的引用了。然后把这 val(XXXMoney) 传到反序化处理里面，进行反序列化各个字段的赋值赋值是一个嵌套循环的过程，会不断的从当前类中获取已有的属性，进行这个属性其他字段的赋值。

640?wx_fmt=png