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重新生成緩存所以不報錯。