serialVersionUID不一致导致的故障总结
问题描述：
系统发布之后线上日志大量报错dubbo服务异常，手动调一次dubbo请求正常，貌似报错是随机出现的，log如下，（还有一个现象是，过了大约二十多分钟后 再无报错信息）
2017-12-21 22:50:04.723 [DubboServerHandler-10.200.16.149:20880-thread-162] ERROR c.l.e.p.common.util.SerializeUtils - traceId:[] - Failed to deserialize
java.lang.Exception: Failed to deserialize
at com.lianjia.ehr.personnel.common.util.SerializeUtils.deserialize(SerializeUtils.java:45) ~[common-1.0-SNAPSHOT.jar:na]
at com.lianjia.ehr.personnel.common.util.SpringRedisCache.toValueWrapper(SpringRedisCache.java:103) [common-1.0-SNAPSHOT.jar:na]
at com.lianjia.ehr.personnel.common.util.SpringRedisCache.get(SpringRedisCache.java:55) [common-1.0-SNAPSHOT.jar:na]
at org.springframework.cache.interceptor.AbstractCacheInvoker.doGet(AbstractCacheInvoker.java:68) [spring-context-4.3.1.RELEASE.jar:4.3.1.RELEASE]
at org.springframework.cache.interceptor.CacheAspectSupport.findInCaches(CacheAspectSupport.java:533) [spring-context-4.3.1.RELEASE.jar:4.3.1.RELEASE]
at org.springframework.cache.interceptor.CacheAspectSupport.findCachedItem(CacheAspectSupport.java:499) [spring-context-4.3.1.RELEASE.jar:4.3.1.RELEASE]
at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:389) [spring-context-4.3.1.RELEASE.jar:4.3.1.RELEASE]
at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:327) [spring-context-4.3.1.RELEASE.jar:4.3.1.RELEASE]
at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:61) [spring-context-4.3.1.RELEASE.jar:4.3.1.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.3.1.RELEASE.jar:4.3.1.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655) [spring-aop-4.3.1.RELEASE.jar:4.3.1.RELEASE]
at com.lianjia.ehr.personnel.facade.org.OrgFacadeImpl$$EnhancerBySpringCGLIB$$a20f67cd.getOrg(<generated>) [facade-1.0-SNAPSHOT.jar:na]
at com.alibaba.dubbo.common.bytecode.Wrapper5.invokeMethod(Wrapper5.java) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:64) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.lianjia.ehr.personnel.facade.filter.LogTraceFilter.invoke(LogTraceFilter.java:33) [facade-1.0-SNAPSHOT.jar:na]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.lianjia.hawkeye.client.dubbo.CatTransaction.invoke(CatTransaction.java:63) [hawk-client-0.9.1-20170720.052006-3.jar:na]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:60) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:132) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:68) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:108) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52) [dubbo-1.0.1.6.jar:1.0.1.6]
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82) [dubbo-1.0.1.6.jar:1.0.1.6]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_111]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_111]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_111]
Caused by: java.io.InvalidClassException: com.lianjia.ehr.personnel.api.org.dto.OrgDTO; local class incompatible: stream classdesc serialVersionUID = 1980543633274099003, local class serialVersionUID = 346175740350971872
at java.io.ObjectStreamClass.initNonProxy(ObjectStreamClass.java:616) ~[na:1.8.0_111]
at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1630) ~[na:1.8.0_111]
at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1521) ~[na:1.8.0_111]
at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1781) ~[na:1.8.0_111]
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1353) ~[na:1.8.0_111]
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:373) ~[na:1.8.0_111]
at com.lianjia.ehr.personnel.common.util.SerializeUtils.deserialize(SerializeUtils.java:38) ~[common-1.0-SNAPSHOT.jar:na]
... 43 common frames omitted
|
问题排查过程：
首先分析上线代码改动点：这次发布涉及dubbo相关改动是：dubbp接口 api的对象DTO serialVersionUID 序列号有改动，
根据日志报错来看 看起来像是 因为序列号变了 导致调用方在反序了化时失败，但是奇怪的是，就算反序列化失败也应该是调用方报错打log，我们是dubbo接口服务提供方， 为什么会抛异常呢？
dubbo的接口方法如下
@Cacheable(value = "facadeCache", key = "#root.methodName + ':' + #root.args[0]")
@Override
public OrgDTO getOrg(Long id) {
OrgDTO orgDTO = null;
if (id != null) {
Org org = orgService.getOrg(id);
if (org != null) {
orgDTO = new OrgDTO();
BeanUtils.copy(org, orgDTO);
}
}
return orgDTO;
}
|
dubbo接口有缓存，根据：方法名+第一个参数 作为缓冲的key值 看了下cache配置如下
<bean id="cacheService" class="com.lianjia.service.cache.CacheService">
<constructor-arg index="0" name="url" value="${mvn.redis.url}"/>
</bean>
<cache:annotation-driven cache-manager="cacheManager"/>
<bean id="simpleCacheManager" class="org.springframework.cache.support.SimpleCacheManager">
<property name="caches">
<list>
<!--<bean class="org.springframework.cache.support.NoOpCacheManager" />-->
<!--<bean id="springRedisCache" class="com.lianjia.ehr.personnel.common.util.SpringRedisCache"-->
<!--c:name="orgServiceCache" c:prefix="org:v1" c:expire="300" c:cacheService-ref="cacheService"/>-->
<bean id="springRedisCache" class="com.lianjia.ehr.personnel.common.util.SpringRedisCache"
c:name="facadeCache" c:prefix="facade:v1" c:expire="1800" c:cacheService-ref="cacheService"/>
</list>
</property>
</bean>
<bean id="cacheManager" class="org.springframework.cache.support.CompositeCacheManager">
<property name="cacheManagers">
<list>
<ref bean="simpleCacheManager"/>
</list>
</property>
<property name="fallbackToNoOpCache" value="true"/>
</bean>
|
SpringRedisCache类代码如下
@Override
public <T> T get(Object key, Class<T> type) {
ValueWrapper valueWrapper = get(key);
if (valueWrapper != null && type != null && !type.isInstance(valueWrapper.get())) {
throw new IllegalStateException("Cached value is not of required type [" + type.getName() + "]: " + valueWrapper.get());
}
return (T) valueWrapper.get();
}
@Override
public <T> T get(Object key, Callable<T> valueLoader) {
return (T) get(key);
}
@Override
public void put(Object key, Object value) {
if (key == null || value == null) {
return;
}
cacheService.set(getKeyBytes(key), SerializeUtils.serialize(value), expire);
logger.info("添加缓存key:{}, value:{}", key, value);
}
|
问题原因：
是dubbo接口缓存的问题，首先查到dubbo接口后会把对象put到redis缓存里，对象会进行序列话操作此时是 把对象之前旧的序列号 serialVersionUID 比如是1 （后来改动为2）进行序列话生成字节流存储在缓存里，现在有调用方调用，key一致（方法名+第一个参数）时从缓存取出，先进行对象的反序列化，此时serialVersionUID变为2了 ，所以反序列化失败，（正常情况是反序列化成功后生成对象，然后走Dubbo默认使用的Hessian序列化方式，而不是java的序列化）
并且缓存有效时间是30分钟，到时间后缓存自动失效，调dubbo接口存入缓存时候按照serialVersionUID改动后的2序列化，再次从缓存取数据时候 还是用serialVersionUID改动后的2 反序列化是正常的，这个符合问题发生的现象
一开始随机性失败的原因：
项目刚启动的时候，缓存没到期的，是从redis取数据会报错，而对于缓存到期的，是按照新的serialVersionUID重新生成缓存所以不报错。
