背景： 测试环境中某次升级后，Jedis调用时出现诡异的ClassCastException，代码堆栈如下： java.lang.ClassCastException: [B cannot be cast to java.lang.Long at redis.clients.jedis.Connection.getIntegerReply(Connection.java:222) at redis.clients.jedis.Jedis.hset(Jedis.java:606) ... 有时候，也会报Unknown reply:的异常。 每次启动1小时内必现。

排查过程：

1. 首先看一下jedis的源码，看看什么情况下可能出现这个问题，相应的源代码如下：

Connection.java:

219  public Long getIntegerReply() {

220    flush();

221    pipelinedCommands--;

222    return (Long) readProtocolWithCheckingBroken();

223  }

...

295 protected Object readProtocolWithCheckingBroken() {

296    try {

297      return Protocol.read(inputStream);

298    } catch (JedisConnectionException exc) {

299      broken = true;

300      throw exc;

301    }

302  }

...

Protocol.java:

204 public static Object read(final RedisInputStream is) {

205    return process(is);

206 }

...

139 private static Object process(final RedisInputStream is) {

140

141 final byte b = is.readByte();

142    if (b == PLUS_BYTE) {

143      return processStatusCodeReply(is);

144    } else if (b == DOLLAR_BYTE) {

145      return processBulkReply(is);

146    } else if (b == ASTERISK_BYTE) {

147      return processMultiBulkReply(is);

148    } else if (b == COLON_BYTE) {

149      return processInteger(is);

150    } else if (b == MINUS_BYTE) {

151      processError(is);

152      return null;

153    } else {

154      throw new JedisConnectionException("Unknown reply: " + (char) b);

155    }

156  }

显然是，hset调用Connection.getIntegerReply()是期待Protocol.process()返回Long，然而返回了byte[]对象，应该是走到了错误的if else分支（当b == DOLLAR_BYTE或b == ASTERISK_BYTE时才会返回byte[]对象，最后一个else分支会报Unknown reply异常），问题定位就在这里，应该是从RedisInputStream(redis服务器端)读取到了错误的内容。

首先，基本可以排除高并发下redis服务器返回错误内容，因为出问题的应用并发并不高，我们生产环境使用jedis处理过比这高得多的并发，从来没碰到过这个错误，再加上是某次升级后碰到的，初步怀疑是升级的代码有什么特殊的场景。

2. 网上搜索一圈后也有其他人遇到这个问题

    https://github.com/xetorthio/jedis/issues/186

    https://www.jianshu.com/p/d78d0009a116

    https://my.oschina.net/jrrx/blog/1634837

    看了一下分析的过程，基本上都属于使用不当，分为两种情形，一种是多线程下共享Jedis实例，一种是使用JedisPool，但并没有遵守Pool的使用规范，没有在使用完后的finally方法块中调用jedis.close()方法。 注：Jedis设计为非线程安全，不支持多线程共享一个Jedis使用，如果使用JedisPool，则规范的调用方式为：

    Jedis jedis = null;

    try {

        jedis = jedisPool.getResource();

        jedis.xxx();

        ....

    } catch(Throwable t) {

        ...

    } finally {

        if(jedis != null) {

            try {

                jedis.close();

            } catch(Throwable t) {

                ....

            }

        }

    }

    唯一特殊的一个案例是，https://my.oschina.net/jrrx/blog/1634837 中提到TimeoutException之后引发ClassCastException，究其原因，还是没有在正确的地方调用jedis.close方法，确保有问题的jedis被销毁。

    实际上，深入看下jedis的代码，读写流或处理的过程中会捕捉IOException以及通用的Exception（注意：jedis的源代码里catch的是Exception，而非Throwable），并将当前jedis实例的isBroken标识置为true，在jedis.close()被正确调用的情况下，会将该实例销毁，如果是连接池模式，则会同时从pool中移除“已损坏”的jedis实例，确保应用层下次调用getResource()方法，返回的是正常或新创建的实例。

3. 虽然对网上的几个类似问题提出的可能是由于多线程导致的分析结果存疑，但从现象上看确实很像，那就先确认一下有没有可能Jedis或JedisPool（底层使用的是commons-pool2）在多线程并发时可能出现状态错误，或者pool返回正在被其它线程使用的实例，这个虽然不容易验证，但是终归还是有办法做到的，直接重载或修改Jedis、JedisPool、commons-pool2的关键的几个地方的源码，加上调试日志，验证一下JedisPool有没有在returnResource一个Jedis实例之前，同时又将相同的实例分配给了下一个并发的线程，具体代码就不贴了，总之很曲折，加调试代码比较简单，曲折的是调试的过程中发现了更诡异的问题：在JedisPool makeObject（用于给pool创建新Jedis对象）、getResource（应用层从pool中获取Jedis对象）、activiateObject（getResource返回对象前会先调用激活方法）以及returnResource(若为Pool模式，jedis.close时自动调用returnResource，而不是自我销毁)方法上分别给操作的jedis实例加上唯一ID，并在上述方法被调用时操作到的jedis唯一ID在日志打印出来，调试的过程中，出现了另一个诡异的现象，偶尔看到某个jedis实例，有activiated的日志，但是竟然找不到makeObject的日志。 于是怀疑logback是不是有丢日志的问题，又开始测试logback，并没有发现丢日志（非常高的并发下也并没有）；考虑到应用及依赖的组件使用了slf4j、commons-logging、jcl-over-slf4j、log4j-over-slf4j、slf4j-log4j12，且后2个jar包实际上是冲突的，并不建议同时使用，这下蛋疼了，原本的问题还没解决，又引出了新的棘手的问题，而且日志的问题还不能说先放一边再说，因为排查的过程会需要打印大量日志，必须依赖日志系统，总不能IDE里debug直接吧。。。新的问题又排查了半天，无果，无奈只能先搁置了。

4. 不管怎么样，既然是升级后出现的问题，还是用屡试不爽的排除法，开发同学review升级的代码，确认增加了一个小模块，主要跟redis的交互代码如下：

private Cache<String, Integer> cache =

            CacheBuilder.newBuilder()

                    .expireAfterWrite(LOCAL_CACHE_TIME_MS, TimeUnit.MILLISECONDS)

                    .initialCapacity(1024)

                    .removalListener((RemovalListener<String, Integer>) notification -> onRemoval(notification.getKey()))

                    .build();

}

private void onRemoval(String field) {

    try {

        String value = redisClient.hget(redisKey, field);

        if(value ...) {

            redisClient.hdel(redisKey, field);

        } else {

            cache.put(field, Integer.parseInt(value));

        }

    } catch (Exception e) {

        logger.error(e.getMessage(), e);

    }

}

...

public void doUpdateSomething() {

    try {

        ...

        if(...) {

            ...

        } else {

            ...

            loadingCache.put(field, value);

            redisClient.hset(redisKey, field, String.valueOf(current));

            // 设置 key 的过期时间为一个小时，主要是作为清除缓存的作用

            redisClient.expire(redisKey, REDIS_KEY_EXPIRE_SECONDS);

        }

    } catch(Exception ex) {

        logger.error(...);

    }

}

把整块代码逻辑干掉，上面的问题没有了，确定是升级的逻辑引发的bug；然后逐个函数排除，很快定位到是onRemoval函数的问题，将onRemoval函数去掉之后，问题也消失了，review onRemoval代码，发现这个函数使用上确实有问题，应用层的逻辑很简单，想在onRemoval回调函数中对expireAfterWrite过期的key做处理，如果redis中存在，说明这个key没有真正过期，再put加载回本地缓存。实际上，guava对onRemoval处理是很多情况下都会触发onRemoval回调，而不仅仅是当key过期或超过大小被移除时调用，正常put也可能触发REPLACE类型的removal，查看其源码即很容易发现该回调接口的完整传参是RemovalNotification对象：

public final class RemovalNotification<K, V> implements Entry<K, V> {

  @Nullable private final K key;

  @Nullable private final V value;

  private final RemovalCause cause;

  RemovalNotification(@Nullable K key, @Nullable V value, RemovalCause cause) {

    this.key = key;

    this.value = value;

    this.cause = checkNotNull(cause);

  }

}

其中，RemovalCause是一个枚举类型，完整的枚举值包括：

/**

* The entry was manually removed by the user. This can result from the user invoking

* {@link Cache#invalidate}, {@link Cache#invalidateAll(Iterable)}, {@link Cache#invalidateAll()},

* {@link Map#remove}, {@link ConcurrentMap#remove}, or {@link Iterator#remove}.

*/

EXPLICIT

/**

* The entry itself was not actually removed, but its value was replaced by the user. This can

* result from the user invoking {@link Cache#put}, {@link LoadingCache#refresh}, {@link Map#put},

* {@link Map#putAll}, {@link ConcurrentMap#replace(Object, Object)}, or

* {@link ConcurrentMap#replace(Object, Object, Object)}.

*/

REPLACED

/**

* The entry was removed automatically because its key or value was garbage-collected. This

* can occur when using {@link CacheBuilder#weakKeys}, {@link CacheBuilder#weakValues}, or

* {@link CacheBuilder#softValues}.

*/

COLLECTED

/**

* The entry's expiration timestamp has passed. This can occur when using

* {@link CacheBuilder#expireAfterWrite} or {@link CacheBuilder#expireAfterAccess}.

*/

EXPIRED

/**

* The entry was evicted due to size constraints. This can occur when using

* {@link CacheBuilder#maximumSize} or {@link CacheBuilder#maximumWeight}.

*/

SIZE

而且，查看guava的源码会发现，cache的清理并不一定是后台定时器触发，而是put完成后会立即出发清理的过程

如果onRemoval方法中再调用cache.put方法，而且put的key还是onRemoval的key（例如上面这段业务逻辑），就会触发无限循环递归，最终的结果就是StackOverflowError。

将上述代码修复一下：

private void onRemoval(RemovalNotification notification) {

    if(!notification.wasEvicted() || notification.getCause() != RemovalCause.EXPIRED) {

        return;

    }

    try {

        String value = redisClient.hget(redisKey, field);

        if(value ...) {

            redisClient.hdel(redisKey, field);

        } else {

            cache.put(field, Integer.parseInt(value));

        }

    } catch (Exception e) {

        logger.error(e.getMessage(), e);

    }

}

测试，问题就解决了。

3. BUG虽然修复了，但是。。。，看了半天，跟redis有毛关系啊，为毛会引发ClassCastException，而不是StackOverflowError，刚刚没有提到的是，后台日志从头到尾没有看到任何StackOverflowError的日志，除了日志里看到ClassCastException，JVM也没有停止运行。所以，想要探查个究竟，还得再排查一轮。上面的递归调用本身是很好确认的，在onRemoval里加调试日志就能看到日志被递归输出了，但是看guava处理onRemoval的源码：

void processPendingNotifications() {

    RemovalNotification<K, V> notification;

    while ((notification = removalNotificationQueue.poll()) != null) {

        try {

            removalListener.onRemoval(notification);

        } catch (Throwable e) {

            logger.log(Level.WARNING, "Exception thrown by removal listener", e);

        }

    }

}

按理说，StackOverflowError继承了Throwable，所以guava cache处理onRemoval回调如果发生StackOverflow的话，应该会捕捉该错误，并输出到日志里，但是应用的日志里一条StackOverflowError都没有，不管复现多少次这个BUG，也没有一条StackOverflowError日志。各种方法尝试了很久，依然没有头绪，直到在应用层onRemoval回掉函数里try catch(Exception)改成try catch(Throwable)之后偶然发现了一条不太一样的日志：

error onRemoval: Could not initialize class java.util.logging.LogRecord

    java.lang.NoClassDefFoundError: Could not initialize class java.util.logging.LogRecord

    at java.util.logging.Logger.log(Logger.java:873) ~[na:1.8.0_25]

    at com.google.common.cache.LocalCache.processPendingNotifications(LocalCache.java:1958) [guava-18.0.jar:na]

    ...

这个错误报的依然莫名其妙，依然不是StackOverflowError，却冒出个无厘头的异常，乍一看还以为是前面提到的应用中几个依赖的日志组件包太多了，冲突导致的，仔细一想，不大对劲，这个是JDK自带的日志框架，怎么会NoClassDefFound呢，仔细一想才恍然大悟，StackOverflowError啊，我们在排查的错误是StackOverflowError，堆栈满了，任何函数调用（当然也包括logger.error(),System.out.println()等等）都需要先压栈，所以StackOverflowError之后，任何函数调用都可能是继续抛出异常StackOverflowError，所以，StackOverflowError 永！远！不！会！输！出！到！日！志！里！（当然，如果使用nohup启动的话，JVM底层是有机会输出到控制台的，但是，java应用层不行！）。

想通了这一点，前面所有问题全都迎刃而解了，StackOverflowError既然可以影响日志输出，当然也可以影响Jedis的任何函数调用！出问题的流程大致是这样的：

    (1) 递归调用onRemoval过程中，在onRemoval内redisClient.hget内部stack overflow（具体在哪个函数达到overflow的临界点不定，有一定的概率会刚好在读写socket流时恰好达到临界点，则会触发ClassCastException）

    (2) 上一步触发的StackOverflowError，被guava的processPendingNotifications函数捕捉，并试图打印日志，但是logger.log会继续触发StackOverflowError，异常抛出过程中中断递归，跳出guava cache的put方法，继续执行（应用层貌似正常，并没有一直陷入递归死循环的魔咒），但是由于该Jedis实例的socket流由于前面的stack overflow其实只被读取了一半，Jedis实例实际上是处在broken的状态（Jedis只会捕捉读写过程中的IOException，StackOverflowError时并不会将jedis实例标识为broken）

    (3) 当Jedis实例再次被当成健康的实例返回给应用层时，由于底层的Socket流并非初始化状态，任何操作都可能读到脏数据，从而触发ClassCastException

4. 验证：基于上面的假设，以及查看Jedis的源代码，只有当读取Socket InputStream过程中发生stack overflow，才可能引发后续的ClassCastException，是时候精心设计测试用例验证这个假设了。设计测试用例前，首先要始终小心一点，Stack overflow的时候，日志或任何函数都会失效，但是简单的赋值操作还是不受Stack overflow影响的，因此，测试用例设计如下：

    (1) 模拟递归调用逻辑，并在递归调用的函数里调用jedis

    (2) 递归调用时try...catch(StackOverflowError over)，并在catch块中记录发生stack overflow的次数并将异常及堆栈存入一个数组里（不调任何函数）：

            ++stackOverflowErrorCount;

            if(stackOverflowErrorCount <= MAX_STACK_OVERFLOW_ERROR_COUNT) {

                lastStackOverflowErrors[stackOverflowErrorCount - 1] = over;

            }

    (3) 当检测到ClassCastException(复现问题)时，跳出递归，测试用例退出前，并将暂存的异常堆栈打印出来

    果然抓到了SocketInputStream.read时发生StackOverflowError的现场：

    java.lang.StackOverflowError

        at java.net.SocketInputStream.read(SocketInputStream.java:157)

        at java.net.SocketInputStream.read(SocketInputStream.java:121)

        at java.net.SocketInputStream.read(SocketInputStream.java:107)

        at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:195)

        at redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:40)

        at redis.clients.jedis.Protocol.process(Protocol.java:141)

        at redis.clients.jedis.Protocol.read(Protocol.java:205)

        at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:297)

        at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:216)

        at redis.clients.jedis.Connection.getBulkReply(Connection.java:205)

        at redis.clients.jedis.Jedis.hget(Jedis.java:622)

5. 总结：一切都是StackOverflow惹的祸！小结一下：

    (1) 当出现StackOverflowError时，日志里很可能看不到相应的异常日志（即便应用层try...catch）

    (2) 当StackOverflowError发生时，应用层出现任何诡异的现象都是可能的

    (3) 通常，StackOverflowError是由于误引入了循环递归逻辑，但很多框架或应用层出于健壮性考虑，会try...catch(Throwable)，此时，可能会“恰巧”意外中断递归逻辑，即便是通过jstack去查看问题现场的堆栈，也不一定能看到堆栈里有递归，因为，当你运行jstack的时候，递归很可能已经因为异常跳出去了，貌似已经恢复了，其实内部不一定哪里状态是异常的