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重新生成缓存所以不报错。