redisson bug分析

1.背景

生产环境操作的redis的框架原先使用的是jedis，基于spring-data-redis封装的template进行读写。因为项目当中也用到了分布式锁，分布式锁的实现直接使用的开源框架redissson。考虑到以下的区别：

• jedis本身是基于阻塞I/O，且其方法调用都是同步的，程序流需要等到socket处理完I/O才能执行，不支持异步，jedis客户端实例不是线程安全的，需要通过连接池来使用jedis。

• redisson使用非阻塞的I/O和基于Netty框架的事件驱动的通信层，其方法调用是异步的。redisson的API是线程安全的，可以操作单个redisson连接来完成各种操作。

且项目中jedis与redisson并存，那么希望直接通过redisson来完成redis的所有操作，包括正常的缓存读写和分布式锁。翻看了redisson的文档之后，发现其也支持spring-data-redis封装template进行操作，于是对项目进行了改造上线。在上线之后，我们缓存出现了不少问题，以下是部分的日志：

第一张截图是数据写入缓存超时，第二张截图是ping操作超时，出现的时间没有固定的规律，属于偶现。

2. 问题分析

截图中的问题不是同一个，我们暂且将其归为问题1和问题2，问题1为写入超时，问题2为ping超时（ping操作是redisson为了进行连接检测和重新连接断开的链接，使用pingConnectionInterval参数进行频率控制，默认30s执行一次）。首先尝试分析问题1写入超时，我们很容易想到，写入操作是不是redis服务器本身存在问题，于是我们第一时间联系了运维，查看了redis的慢查日志，统计了redis的响应延时，结果发现redis服务端没有任何问题，且在redisson改造上线前，使用jedis时没有出现任何redis写入或者读取操作的问题，于是我们认为redis服务器本身是没有问题的。同时，我们看到了问题2ping超时，那么会不会是网络问题导致的？

2.1 网络连接

对于问题2，我们查阅了网上的相关资料，大部分的资料分析的是redis服务端关闭了连接，而redisson client端不知道，于是client端使用了该链接从而导致错误的发生，解决方案是设置pingConnectionInterval参数。但是，在我们使用的redisson版本中，pingConnectionInterval参数默认30s，也就是说，每30s就会对连接进行一次检测即ping命令，理论上来说服务端不可能在如此短的时间内就对连接进行关闭。为防万一，我们也查看了服务端的配置，首先查看tcp keepalive的配置（命令为sysctl -a |grep tcp_keepalive）如下：

熟悉tcp的同学应该知道，tcp可以有长连接和短连接（此处不同于http的长连接和短连接），在有些场景中，我们希望连接能长期保持以减少重复断开连接造成的系统开销，因此会使用长连接，不同的redis客户端一般都使用长连接。在使用长连接时，客户端（两端都是可能的）可能意外断电、死机、崩溃、重启，还是中间路由网络无故断开，这些TCP连接并未来得及正常释放，那么，连接的另一方并不知道对端的情况，它会一直维护这个连接，长时间的积累会导致非常多的半打开连接，造成服务端系统资源的消耗和浪费，因此就有了保活探测机制（keepalive）。在上图的配置中，

net.ipv4.tcp_keepalive_time=30

表示允许的空闲时长为30s，即在客服端最后一次发送之后，过了30s，服务端会进行主动的探测。探测的次数和时间间隔由

net.ipv4.tcp_keepalive_probes

和

net.ipv4.tcp_keepalive_intvl

控制，上图中

net.ipv4.tcp_keepalive_intvl=15

表示探测的时间间隔为15s，

net.ipv4.tcp_keepalive_probes=5

表示探测次数为5次， 也就是说，在客户端发送了报文之后，30s没有新的报文，服务端会往客户端发送一个keepalive探测包，如果客户端没有响应，那么间隔15s之后会继续发keepalive探测包，如果一直没有响应，那么服务端在发送5次之后会主动断开连接，从上面的配置看，如果客户端一直没有响应redis服务端的keepalive探测包，那么在30 + 5*15 =105s之后，redis服务端会关闭这个连接。基于上面的论述，redisson客户端会每隔30s发送一次ping命令，理论上来说redis服务端不可能会主动关闭连接而造成redisson客户端无感知。为了验证连接是否还在，我们也查看了redis服务端的连接情况(netstat -no|grep 6379):

最后一列的keepalive说明tcp keepalive的是开启的，也就是说redis服务端会进行探测保活。这里的结果多列，我们来分析一下具体的含义，首先netstat命令中的-o参数的含义是输出相关的网络定时器：

-o, --timersInclude information related to networking timers.

结果中最后一列的含义（man netstat）如下：

Timer(this needs to be written)

一头冷汗，官方的文档竟然没写，直接拷贝一下网上的资料如下：

第一列，一般有一下几种状态；keepalive - #表示是keepalive的时间计时on - #表示是重发(retransmission)的时间计时off - #表示没有时间计时timewait - #表示等待(timewait)时间计时第二列，(51.16/0/0) -> (a/b/c)a - #计时时间值(当第一列为keepalive的时候，a代表keepalive计时时间；当第一列为on的时候，a代表重发(retransmission)的时间计时；当第一列为timewait的时候，a代表等待(timewait)的时间计时)b - #已经产生的重发(retransmission)次数c - #keepalive已经发送的探测(probe)包的次数

从以上的说明，我们可以看出截图中的连接不存发送探测包的情况，也即不存在空闲的情况（因为一直客户端每隔30s进行一次ping）。但是截图上有一列的计时是51.16，这大于了系统的30s，这又是怎么来的呢？实际上在应用层面可以自行设定tcp keepalive的时间，这里是因为redis服务器自身进行了设定，具体的配置如下：

# Close the connection after a client is idle for N seconds (0 to disable)
timeout 0

# TCP keepalive.
#
# If non-zero, use SO_KEEPALIVE to send TCP ACKs to clients in absence
# of communication. This is useful for two reasons:
#
# 1) Detect dead peers.
# 2) Take the connection alive from the point of view of network
# equipment in the middle.
#
# On Linux, the specified value (in seconds) is the period used to send ACKs.
# Note that to close the connection the double of the time is needed.
# On other kernels the period depends on the kernel configuration.
#
# A reasonable value for this option is 60 seconds.
tcp-keepalive 60


对于redis服务端而言，实际的keepalive空闲时间是60s。至此，我们发现，在网络连接层面是不会出现问题的，那么，问题到底在哪里？回到日志，日志有详细的错误堆栈信息，是不是可以从这里再挖出一些有用的信息呢？

2.2 问题复现

在问题1的日志里，可以看到此处的逻辑是set操作，在spring-data-redis的template操作最终走到了RedissonConnection的write操作，而后是sync阻塞等待实际的write结果，那么write阶段是否有异常发生了，我们尝试找了更细节的日志：

2022-01-24 02:55:39.685 [http-nio-8080-exec-6] ERROR [o.a.c.c.C.[.[.[.[dispatcherServlet]:175] [TID:N/A] - Servlet.service() for servlet [dispatcherServlet] in context with path [/cmccplus] threw exception
org.springframework.dao.InvalidDataAccessApiUsageException: Unexpected exception while processing command; nested exception is org.redisson.client.RedisException: Unexpected exception while processing command
 at org.redisson.spring.data.connection.RedissonExceptionConverter.convert(RedissonExceptionConverter.java:52)
 at org.redisson.spring.data.connection.RedissonExceptionConverter.convert(RedissonExceptionConverter.java:35)
 at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
 at org.redisson.spring.data.connection.RedissonConnection.transform(RedissonConnection.java:195)
 at org.redisson.spring.data.connection.RedissonConnection.syncFuture(RedissonConnection.java:190)
 at org.redisson.spring.data.connection.RedissonConnection.sync(RedissonConnection.java:356)
 at org.redisson.spring.data.connection.RedissonConnection.write(RedissonConnection.java:722)
 at org.redisson.spring.data.connection.RedissonConnection.setEx(RedissonConnection.java:530)
 at org.springframework.data.redis.connection.DefaultStringRedisConnection.setEx(DefaultStringRedisConnection.java:1138)
 at org.springframework.data.redis.core.DefaultValueOperations$8.potentiallyUsePsetEx(DefaultValueOperations.java:337)
 at org.springframework.data.redis.core.DefaultValueOperations$8.doInRedis(DefaultValueOperations.java:330)
 at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:223)
 at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:190)
 at org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:97)
 at org.springframework.data.redis.core.DefaultValueOperations.set(DefaultValueOperations.java:325)
 at com.cmcc.hy.plus.biz.auth.JwtAuthenticationTokenFilter.doFilterInternal(JwtAuthenticationTokenFilter.java:150)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:96)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
 at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
 at org.apache.catalina.core.StandardHostValve.invoke$original$j3CdN2QH(StandardHostValve.java:135)
 at org.apache.catalina.core.StandardHostValve.invoke$original$j3CdN2QH$accessor$lXTjUmdl(StandardHostValve.java)
 at org.apache.catalina.core.StandardHostValve$auxiliary$mFQ4Aq8A.call(Unknown Source)
 at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
 at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
 at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
 at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
 at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732)
 at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
 at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
 at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
 at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
 at java.lang.Thread.run(Thread.java:748)
Caused by: org.redisson.client.RedisException: Unexpected exception while processing command
 at org.redisson.command.CommandAsyncService.convertException(CommandAsyncService.java:328)
 at org.redisson.command.CommandAsyncService.get(CommandAsyncService.java:128)
 at org.redisson.spring.data.connection.RedissonConnection.syncFuture(RedissonConnection.java:188)
 ... 50 common frames omitted
Caused by: java.lang.NullPointerException: null
 at org.redisson.client.handler.CommandEncoder.encode(CommandEncoder.java:130)
 at org.redisson.client.handler.CommandEncoder.encode(CommandEncoder.java:99)
 at org.redisson.client.handler.CommandEncoder.encode(CommandEncoder.java:55)
 at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:107)
 at org.redisson.client.handler.CommandEncoder.write(CommandEncoder.java:75)
 at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:738)
 at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:730)
 at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:816)
 at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:723)
 at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:120)
 at org.redisson.client.handler.CommandBatchEncoder.write(CommandBatchEncoder.java:45)
 at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:738)
 at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:801)
 at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:814)
 at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:794)
 at org.redisson.client.handler.CommandsQueue.write(CommandsQueue.java:84)
 at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:738)
 at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:730)
 at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:816)
 at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:723)
 at io.netty.channel.ChannelDuplexHandler.write(ChannelDuplexHandler.java:106)
 at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:738)
 at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:730)
 at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:38)
 at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:1081)
 at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1128)
 at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:1070)
 at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
 at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
 at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:446)
 at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 ... 1 common frames omitted


这个日志比较详细，可以看到这里抛出了NullPointerException，具体抛出了地方是redisson的CommandEncoder，这就很有意义了。同时，我们发现了这个异常的原因是com.cmcc.hy.plus.biz.auth.JwtAuthenticationTokenFilter.doFilterInternal(JwtAuthenticationTokenFilter.java:150)，在这一行，我们真的发现了系统的一个bug，这里有可能会出现使用redisTemplate set null的情况，因此，我们在IDE中模拟了这个错误，发现使用基于redisson的redisTemplate set null的确会出现CommandEncoder的NullPointerException，堆栈信息也一样，到这里我们发现好像事情在变得逐渐明朗起来。但是，前述的问题1和问题2是怎么来的呢，好像和NullPointerException是完全不同的问题，两者是不是有什么联系呢？基于此，我们对日志进行了更多了分析，

分析之后发现了一个有趣的现象，在CommandEncoder的NullPointerException的周边，都会出现要么是问题1或者问题2的错误，有较强的规律

。那么是不是CommandEncoder NullPointerException蔓延出了其他的错误呢？巧合的是，我们在本地IDE复现了这个问题，在验证CommandEncoder NullPointerException时，测试用例并没有关闭，在30s之后，出现了Ping异常：

[redisson-timer-4-1] ERROR [o.r.c.handler.PingConnectionHandler:77] [TID: N/A] - Unable to send PING command over channel: [id: 0x3564ed6a, L:/2.0.4.28:61450 - R:172.21.41.10/172.21.41.10:6379]
org.redisson.client.RedisTimeoutException: Command execution timeout for command: (PING), params: [], Redis client: [addr=redis://172.21.41.10:6379]
 at org.redisson.client.RedisConnection.lambda$async$1(RedisConnection.java:251)
 at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:670)
 at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:745)
 at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:473)
 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 at java.lang.Thread.run(Thread.java:748)


之后，我们缩小了ping的间隔时间，以便更好的观察，结果很令人欣慰，在使用redisTemplate set null时，出现CommandEncoder NullPointerException 之后，必然会出现ping异常，走到这里，颇有柳暗花明又一村的感觉！问题2 ping超时已经复现了，事实证明不是网络连接的原因，那么问题1 写入超时呢，是不是同样的问题导致的？按照这个想法，接下来复现的方法就很简单了，在redisTemplate set null之后写入一个正常的数据，结果是出现了写入超时（此处不再贴日志了），且必现！并且在之后的写入和读取操作会一直报错，也就是说这条连接后续的操作会一直出错，直至出现ping异常。ping异常之后的操作将不再报错，这也侧面说明了为何生产环境不会一直报错，至于ping异常之后不会继续出错的原因是PingConnectionHandler（定时发送ping指令的处理器）会将出错的连接close, 如下代码的第18行：

private void sendPing(ChannelHandlerContext ctx) {
 RedisConnection connection = RedisConnection.getFrom(ctx.channel());
 RFuture<String> future;
 if (connection.getUsage() == 0) {
 future = connection.async(StringCodec.INSTANCE, RedisCommands.PING);
 } else {
 future = null;
 }

 config.getTimer().newTimeout(timeout -> {
 if (connection.isClosed() || ctx.isRemoved()) {
 return;
 }

 if (connection.getUsage() == 0
 && future != null
 && (future.cancel(false) || !future.isSuccess())) {
 ctx.channel().close();
 if (future.cause() != null && !future.isCancelled()) {
 log.error(&quot;Unable to send PING command over channel: &quot; + ctx.channel(), future.cause());
 }
 log.debug(&quot;channel: {} closed due to PING response timeout set in {} ms&quot;, ctx.channel(), config.getPingConnectionInterval());
 } else {
 sendPing(ctx);
 }
 }, config.getPingConnectionInterval(), TimeUnit.MILLISECONDS);


同时，ConnectionWatchdog会尝试进行重连（这里的重连是指RedisConnection，而不是原先的tcp连接）：

 public void channelInactive(ChannelHandlerContext ctx) throws Exception {
 RedisConnection connection = RedisConnection.getFrom(ctx.channel());
 if (connection != null) {
 connection.fireDisconnected();
 if (!connection.isClosed()) {
 if (connection.isFastReconnect()) {
 tryReconnect(connection, 1);
 } else {
 reconnect(connection, 1);
 }
 }
 }
 ctx.fireChannelInactive();
 }


在重连之后，会注册一条新的channel，并使用新的RedisConnection进行后续的操作。既然问题已经复现并且基于此进行了简单的分析，那么要解决这个问题实际也比较简单，在我们的应用代码里出现set null bug的地方先做一层判断，就能避免整个redisson问题的蔓延。但是，这里不禁要问，为什么使用jedis的时候没有这个问题？因为jedis在执行命令的时候对所有的key、value都进行了非空校验，而redisson没有！以下是jedis的set代码：

以下是redisson的set代码：

非常遗憾的是，redisson作为一个比较成熟的开源项目，竟然没有做最基本的非空校验，并且出现问题时出现了异常的扩散。走到这里，实际我们已经能解决生产的问题了，至少能保证不会再继续出现写入超时或者ping超时，但是，禀着“知其然而知其所以然”的宗旨，我们不禁要问，到底是什么原因，redisson出现了异常的扩散？

2.3 源码分析

我们先看看redisson set时write方法中的内容：

<T> T write(byte[] key, Codec codec, RedisCommand<?> command, Object... params) {
 RFuture<T> f = executorService.writeAsync(key, codec, command, params);
 indexCommand(command);
 return sync(f);
 }


这是一个异步转同步的过程，

executorService.writeAsync

异步执行操作，

sync

阻塞等待结果。在这方法中

RedisCommand

封装了redis的命令，

params

是命令的参数。在set null的过程中，从之前的日志可以分析出在执行

writeAsync

的过程中出现了问题，堆栈信息表明是

CommandEncoder

抛出了空指针，

CommandEncoder

的作用是对请求的redis指令进行编码，它是一个

MessageToByteEncoder

。它的编码方法如下：

 @Override
 protected void encode(ChannelHandlerContext ctx, CommandData<?, ?> msg, ByteBuf out) throws Exception {
 try {
 out.writeByte(ARGS_PREFIX);
 int len = 1 + msg.getParams().length;
 if (msg.getCommand().getSubName() != null) {
 len++;
 }
 out.writeCharSequence(Long.toString(len), CharsetUtil.US_ASCII);
 out.writeBytes(CRLF);
 
 writeArgument(out, msg.getCommand().getName().getBytes(CharsetUtil.UTF_8));
 if (msg.getCommand().getSubName() != null) {
 writeArgument(out, msg.getCommand().getSubName().getBytes(CharsetUtil.UTF_8));
 }

 for (Object param : msg.getParams()) {
 ByteBuf buf = encode(param);
 writeArgument(out, buf);
 if (!(param instanceof ByteBuf)) {
 buf.release();
 }
 }
 
 if (log.isTraceEnabled()) {
 String info = out.toString(CharsetUtil.UTF_8);
 if (RedisCommands.AUTH.equals(msg.getCommand())) {
 info = info.substring(0, info.indexOf(RedisCommands.AUTH.getName()) + RedisCommands.AUTH.getName().length()) + &quot;(password masked)&quot;;
 }
 log.trace(&quot;channel: {} message: {}&quot;, ctx.channel(), info);
 }
 } catch (Exception e) {
 msg.tryFailure(e);
 throw e;
 }
 }


在以上代码第18行的

encode

方法中，对参数进行具体的编码，null导致此处抛出空指针异常，在这个方法的末尾也捕获了这个异常同时

msg.tryFailure

结束了调用过程并将异常往外抛出，并最终在外层对异常进行封装转换，这里符合set null的异常堆栈信息。那么，它是如何对后面的操作产生影响的呢？我们采用如下的代码进行测试：

 try {
 stringRedisTemplate.opsForValue().set("test-null", null);
 } catch (Exception e) {
 log.error("write null", e);
 }
 try {
 stringRedisTemplate.opsForValue().set("test-normal-write", "1");
 } catch (Exception e) {
 log.error("write normal", e);
 }


代码的逻辑很简单，使用StringRedisTemplate先写入null值，然后再写入一个正常值，观察log。在写入null值时，结果就是之前的堆栈信息，在写入正常值时，错误日志如下：

org.springframework.dao.QueryTimeoutException: Redis server response timeout (3000 ms) occured after 0 retry attempts. Increase nettyThreads and/or timeout settings. Try to define pingConnectionInterval setting. Command: (SET), params: [[116, 101, 115, 116, 45, 110, 111, 114, 109, 97, ...], [49]], channel: [id: 0x5fc67cb9, L:/2.0.4.190:55103 - R:172.21.41.10/172.21.41.10:6379]; nested exception is org.redisson.client.RedisResponseTimeoutException: Redis server response timeout (3000 ms) occured after 0 retry attempts. Increase nettyThreads and/or timeout settings. Try to define pingConnectionInterval setting. Command: (SET), params: [[116, 101, 115, 116, 45, 110, 111, 114, 109, 97, ...], [49]], channel: [id: 0x5fc67cb9, L:/2.0.4.190:55103 - R:172.21.41.10/172.21.41.10:6379]
 at org.redisson.spring.data.connection.RedissonExceptionConverter.convert(RedissonExceptionConverter.java:48)
 at org.redisson.spring.data.connection.RedissonExceptionConverter.convert(RedissonExceptionConverter.java:35)
 at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
 at org.redisson.spring.data.connection.RedissonConnection.transform(RedissonConnection.java:195)
 at org.redisson.spring.data.connection.RedissonConnection.syncFuture(RedissonConnection.java:190)
 at org.redisson.spring.data.connection.RedissonConnection.sync(RedissonConnection.java:356)
 at org.redisson.spring.data.connection.RedissonConnection.write(RedissonConnection.java:722)
 at org.redisson.spring.data.connection.RedissonConnection.set(RedissonConnection.java:490)
 at org.springframework.data.redis.connection.DefaultStringRedisConnection.set(DefaultStringRedisConnection.java:1102)
 at org.springframework.data.redis.core.DefaultValueOperations$7.inRedis(DefaultValueOperations.java:309)
 at org.springframework.data.redis.core.AbstractOperations$ValueDeserializingRedisCallback.doInRedis(AbstractOperations.java:61)
 at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:223)
 at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:190)
 at org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:97)
 at org.springframework.data.redis.core.DefaultValueOperations.set(DefaultValueOperations.java:305)
 at com.cmcc.hy.plus.job.controller.TestController.redis(TestController.java:47)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:498)
 at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
 at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
 at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
 at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
 at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
 at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
 at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
 at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
 at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
 at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:681)
 at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at com.cmcc.hy.plus.common.filter.LoggingFilter.doFilterInternal(LoggingFilter.java:243)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:96)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
 at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
 at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
 at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
 at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
 at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
 at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732)
 at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
 at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
 at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
 at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
 at java.lang.Thread.run(Thread.java:748)
Caused by: org.redisson.client.RedisResponseTimeoutException: Redis server response timeout (3000 ms) occured after 0 retry attempts. Increase nettyThreads and/or timeout settings. Try to define pingConnectionInterval setting. Command: (SET), params: [[116, 101, 115, 116, 45, 110, 111, 114, 109, 97, ...], [49]], channel: [id: 0x5fc67cb9, L:/2.0.4.190:55103 - R:172.21.41.10/172.21.41.10:6379]
 at org.redisson.command.RedisExecutor.lambda$scheduleResponseTimeout$5(RedisExecutor.java:341)
 at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:670)
 at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:745)
 at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:473)
 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
 ... 1 common frames omitted


从日志的表面看，的确就是超时了，第一句话“org.springframework.dao.QueryTimeoutException: Redis server response timeout (3000 ms) occured after 0 retry attempts. Increase nettyThreads and/or timeout settings. Try to define pingConnectionInterval setting. ”表示超过了3000ms还没有响应，3000ms是redisson的响应超时时间，那么这个具体是从哪里来的呢？在我们前面的分析中，redisson的写入操作是一个异步转同步的过程，使用了sync方法阻塞等待future的结果。既然是异步的过程，它是如何控制超时时间的，答案是

org.redisson.command.RedisExecutor#scheduleResponseTimeout

方法，这个方法会起一个定时任务，任务的在3000ms（可配置）之后执行，任务的内容是将操作结果置为超时，也就是说，如果3000ms内该任务没有被cancel掉，就会抛出超时的异常。核心逻辑是这一段代码：

 TimerTask timeoutResponseTask = timeout -> {
 if (isResendAllowed(attempt, attempts)) {
 if (!attemptPromise.cancel(false)) {
 return;
 }

 connectionManager.newTimeout(t -> {
 attempt++;
 if (log.isDebugEnabled()) {
 log.debug("attempt {} for command {} and params {}",
 attempt, command, LogHelper.toString(params));
 }

 mainPromiseListener = null;
 execute();
 }, retryInterval, TimeUnit.MILLISECONDS);
 return;
 }

 attemptPromise.tryFailure(
 new RedisResponseTimeoutException("Redis server response timeout (" + timeoutAmount + " ms) occured"
 + " after " + attempt + " retry attempts. Increase nettyThreads and/or timeout settings. Try to define pingConnectionInterval setting. Command: "
 + LogHelper.toString(command, params) + ", channel: " + connection.getChannel()));
 };

 timeout = connectionManager.newTimeout(timeoutResponseTask, timeoutTime, TimeUnit.MILLISECONDS);


可以看到，timeoutResponseTask中组装了RedisResponseTimeoutException异常。

scheduleResponseTimeout

方法是在何处被调用的呢？从源码可以看到只有一个地方调用了这个方法，这个地方是

org.redisson.command.RedisExecutor#checkWriteFuture

，

checkWriteFuture

的作用是检查写入请求的结果，如果写入成功的话，就会调用这个方法，具体如下：

 connectionFuture.onComplete((connection, e) -> {
 if (connectionFuture.isCancelled()) {
 connectionManager.getShutdownLatch().release();
 return;
 }

 if (!connectionFuture.isSuccess()) {
 connectionManager.getShutdownLatch().release();
 exception = convertException(connectionFuture);
 return;
 }

 sendCommand(attemptPromise, connection);

 writeFuture.addListener(new ChannelFutureListener() {
 @Override
 public void operationComplete(ChannelFuture future) throws Exception {
 checkWriteFuture(writeFuture, attemptPromise, connection);
 }
 });
 });


在上述代码的第15行，表明

writeFuture

有一个Listener，在write操作完成的时候进行检查

checkWriteFuture

。也就是说，在

scheduleResponseTimeout

之前，实际请求已经发出去了，那么redis服务端有没有收到呢？使用redis-cli的monitor功能查看服务端接收到的请求，的确能看到写入的请求：

从截图中可以看到操作是SET，key是test-normal-write，且redis服务端没有收到SET test-null的指令，因为redisson在

CommandEncoder

阶段已经抛出空指针了。从redis的服务端看，对SET操作的处理也非常快，那问题是不是在响应处理这一端出现的呢？接下来我们来看一看redisson在处理请求/响应时到底干了什么，具体可以参考

org.redisson.client.handler.RedisChannelInitializer#initChannel

方法，代码如下：

 @Override
 protected void initChannel(Channel ch) throws Exception {
 initSsl(config, ch);
 
 if (type == Type.PLAIN) {
 ch.pipeline().addLast(new RedisConnectionHandler(redisClient));
 } else {
 ch.pipeline().addLast(new RedisPubSubConnectionHandler(redisClient));
 }

 ch.pipeline().addLast(
 connectionWatchdog,
 CommandEncoder.INSTANCE,
 CommandBatchEncoder.INSTANCE);

 if (type == Type.PLAIN) {
 ch.pipeline().addLast(new CommandsQueue());
 } else {
 ch.pipeline().addLast(new CommandsQueuePubSub());
 }

 if (pingConnectionHandler != null) {
 ch.pipeline().addLast(pingConnectionHandler);
 }
 
 if (type == Type.PLAIN) {
 ch.pipeline().addLast(new CommandDecoder(config.getAddress().getScheme()));
 } else {
 ch.pipeline().addLast(new CommandPubSubDecoder(config));
 }

 ch.pipeline().addLast(new ErrorsLoggingHandler());

 config.getNettyHook().afterChannelInitialization(ch);
 }


代码中可以看到很多熟悉的身影，比如

pingConnectionHandler

、

CommandEncoder

、

connectionWatchdog

。从以上的代码中，我们可以简单画一下输入和输出的pipeline，输出（请求redis）的pipieline如下：

ErrorsLoggingHandler -> CommandsQueue -> CommandBatchEncoder -> CommandEncoder


输入（响应redis，还包括建立连接等）的pipeline如下：

RedisConnectionHandler -> ConnectionWatchdog -> PingConnectionHandler -> CommandDecoder -> ErrorsLoggingHandler


在输出即请求链路上，按我们的分析，set null时在

CommandEncoder

抛出了异常，中断了请求，在set正常值时链路时正常的。在输入即响应链路上，最主要的是

CommandDecoder

，其他要么是处理日志，要么是处理连接事件，这里我们着重分析一下

CommandDecoder

，即解码器。解码的第一步很重要，就是取出对应请求时的操作命令，redisson是这么做的：

 protected QueueCommand getCommand(ChannelHandlerContext ctx) {
 Queue<QueueCommandHolder> queue = ctx.channel().attr(CommandsQueue.COMMANDS_QUEUE).get();
 QueueCommandHolder holder = queue.peek();
 if (holder != null) {
 return holder.getCommand();
 }
 return null;
 }


它从channel中取出了一个queue，然后从queue中peek出了

QueueCommandHolder

作为当前的要处理的命令响应。那既然可以从queue中取，那又是什么时候塞入queue的呢，我们可以看到在请求的pipiline中，有一个

CommandsQueue

，它是在这里把命令塞到queue里面的。

 @Override
 public void write(ChannelHandlerContext ctx, Object msg, ChannelPromise promise) throws Exception {
 if (msg instanceof QueueCommand) {
 QueueCommand data = (QueueCommand) msg;
 QueueCommandHolder holder = new QueueCommandHolder(data, promise);

 Queue<QueueCommandHolder> queue = ctx.channel().attr(COMMANDS_QUEUE).get();

 while (true) {
 if (lock.compareAndSet(false, true)) {
 try {
 queue.add(holder);
 ctx.writeAndFlush(data, holder.getChannelPromise());
 } finally {
 lock.set(false);
 }
 break;
 }
 }
 } else {
 super.write(ctx, msg, promise);
 }
 }


此时，我们已经大致知道queue写入和取出的对应关系，因为peek不会对queue中的数据做remove操作，所以必然有个地方把queue中的数据推出，redisson的做法是在解码之后推出，decode之后会调用如下的方法：

 protected void sendNext(Channel channel) {
 Queue<QueueCommandHolder> queue = channel.attr(CommandsQueue.COMMANDS_QUEUE).get();
 queue.poll();
 state(null);
 }


分析到这里，我们的问题其实基本已经有解了，在案例中stringRedisTemplate set null之后，由于在

CommandEncode

阶段抛出了空指针异常，导致请求没发出去，那么肯定不会有

CommandDecoder

阶段了，根据pipeline的顺序，

CommandsQueue

是在

CommandEncoder

之前执行，这也意味着queue中塞入了set null（指指令1）请求指令，而没有解码阶段将其从queue中推出，这导致在下一个set正常值（指令2）的命令时，请求发到了redis，redis也进行了响应，但是在解码阶段，取出的操作指令是上一个请求（指令1）的，从而解码异常，而且，由于此时取出的是第一次操作的指令（指令1），第二次的指令（指令2）还在等待下一次从queue中取出并处理（promise.tryFailure），进而导致正常set（指令2）的超时。自此，后续所有的请求都会出现错误，因为解码阶段取出的

QueueCommand

永远是上一次请求的，直到

PinConnectionHandler

出错，并断开连接，在

ConnectionWatchDog

的协同处理下重置整个channel的数据。redisson作为一个成熟的开源框架，有这个bug实际是非常不应该的，解决的方案有两种：

• 和jedis一样，在set等操作开始前进行前置的判空校验；

• 在
  CommandEncoder
  的encode抛出异常时，使用final语句将queue中的
  QueueCommandHolder
  推出。

当然，这里更倾向于方案1。

3.总结

在分析redisson为什么会异常蔓延的过程中，实际经历的过程远比文中复杂。一个是redisson出错时的日志误导性比较强，看到错误日志的第一反应，要么是网络出错，要么是redis服务器出错，在分析了很久之后才排除了网络和redis的原因，从而转到分析redisson自身的实现机制。另外，在分析redisson的过程中，最开始的设想其实是在请求阶段关闭了连接，但是没有释放句柄或者引用，这也耗费了比较长的时间。在分析过程中，也打印了不少的TRACE日志，这也帮助排除了不少的错误方向。总而言之，分析问题是个比较耗时的过程，也是个不断学习进步的过程，在这个过程中，熟悉了redisson，熟悉了netty，也为今后自己的应用代码提供了很好的借鉴。