Redisson bug analysis

1. background

Production environment operation redis Our framework used jedis, be based on spring-data-redis Packaged template To read and write . Because distributed locks are also used in the project , The implementation of distributed locks directly uses the open source framework redissson. Consider the following differences ：

• jedis It's based on blocking I/O, And the method calls are synchronous , Program flow needs to wait until socket processed I/O To perform , Asynchronous is not supported ,jedis Client instance is not thread safe , You need to use... Through a connection pool jedis.

• redisson Use non blocking I/O And based on Netty Event driven communication layer of framework , Its method calls are asynchronous .redisson Of API It's thread safe , You can operate a single redisson Connect to complete various operations .

And in the project jedis And redisson Coexist , Then I hope to pass directly redisson To complete redis All operations , Including normal cache reads and writes and distributed locks . Looking at the redisson After the document of , Found that it also supports spring-data-redis encapsulation template To operate , So the project was transformed and launched . After going online , There are many problems with our cache , Here are some logs ：

The first screenshot is data write cache timeout , The second screenshot is ping Operation timeout , There is no fixed rule in the time of occurrence , Belong to occasional .

2.  Problem analysis

The problem in the screenshot is not the same , Let's classify it as a problem for the time being 1 And questions 2, problem 1 Timeout for writing , problem 2 by ping Overtime （ping Operation is redisson For connection detection and reconnection of broken links , Use pingConnectionInterval Parameters for frequency control , Default 30s Do it once ）. First try to analyze the problem 1 Write timeout , It's easy for us to think , Is the write operation redis There is a problem with the server itself , So we contacted the operation and maintenance department for the first time , Look at the redis Check the log slowly , Statistics redis Response delay of , Results found redis There is no problem with the server , And in redisson Before the transformation goes online , Use jedis There is no redis Problems with write or read operations , So we think redis There is no problem with the server itself . meanwhile , We see the problem 2ping Overtime , Will it be caused by network problems ？

2.1  network connections

For questions 2, We checked the relevant information on the Internet , Most of the data analysis is redis The server has closed the connection , and redisson client I don't know , therefore client The end uses the link, which leads to an error , The solution is setup pingConnectionInterval Parameters . however , In what we use redisson In the version ,pingConnectionInterval Parameter default 30s, in other words , Every time 30s The connection will be tested once, that is ping command , Theoretically, the server cannot close the connection in such a short time . Just in case , We also checked the configuration of the server , First of all to see tcp keepalive Configuration of （ The order is sysctl -a |grep tcp_keepalive） as follows ：

be familiar with tcp You should know ,tcp There can be long connections and short connections （ This is different from http Long and short connections of ）, In some scenes , We hope that the connection can be maintained for a long time to reduce the system overhead caused by repeated disconnection , Therefore, long connections will be used , Different redis Clients generally use long connections . When using long connections , client （ Both ends are possible ） The power may be cut off accidentally 、 crash 、 collapse 、 restart , Or the intermediate routing network is disconnected for no reason , these TCP Connect and release normally in the future , that , The other side of the connection doesn't know about the opposite end , It will always maintain this connection , Over time, this can lead to a lot of half open connections , Cause the consumption and waste of system resources on the server , Therefore, there is a keep alive detection mechanism （keepalive）. In the configuration shown above ,

net.ipv4.tcp_keepalive_time=30

Indicates that the allowed idle time is 30s, That is, after the customer service end sends it for the last time , After that 30s, The server will actively detect . The number and time interval of detection are determined by

net.ipv4.tcp_keepalive_probes

and

net.ipv4.tcp_keepalive_intvl

control , Above picture

net.ipv4.tcp_keepalive_intvl=15

Indicates that the time interval of detection is 15s,

net.ipv4.tcp_keepalive_probes=5

Indicates that the number of detections is 5 Time ,  in other words , After the client sends the message ,30s No new messages , The server will send a message to the client keepalive Detection bag , If the client does not respond , So the interval 15s After that, I will continue to send keepalive Detection bag , If there is no response , Then the server is sending 5 After that, it will actively disconnect , From the configuration above , If the client has not responded redis Server side keepalive Detection bag , So in 30 + 5*15 =105s after ,redis The server will close the connection . Based on the above discussion ,redisson The client will every 30s Send it once ping command , In theory redis The server cannot actively close the connection and cause redisson The client has no perception . To verify whether the connection is still , We also checked redis The connection of the server (netstat -no|grep 6379):

In the last column keepalive explain tcp keepalive Is open , in other words redis The server will detect and keep alive . The results here are many columns , Let's analyze the specific meaning , First netstat In the command -o The meaning of the parameter is to output the relevant network timer ：

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

The meaning of the last column in the result （man netstat） as follows ：

Timer(this needs to be written)

A cold sweat , The official document was not written , Directly copy the online information as follows ：

First column , Generally, there are several States ;keepalive - # Said is keepalive The timing of on - # It means resend (retransmission) The timing of off - # It means there is no time to time timewait - # Said wait (timewait) The second column of timing ,(51.16/0/0) -> (a/b/c)a - # Timing time value ( When the first column is keepalive When ,a representative keepalive Timing time ; When the first column is on When ,a On behalf of resend (retransmission) The timing of ; When the first column is timewait When ,a For waiting (timewait) The timing of )b - # Retransmissions that have occurred (retransmission) frequency c - #keepalive Probes that have been sent (probe) Number of bags

From the above description , We can see that the connection in the screenshot does not send detection packets , That is, there is no idle situation （ Because the client has been every 30s Do it once. ping）. But the timing of a column on the screenshot is 51.16, This is larger than the system 30s, How did this come about ？ In fact, it can be set at the application level tcp keepalive Time for , This is because redis The server itself is set , The specific configuration is as follows ：

# 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


about redis As for the server side , Actually keepalive Free time is 60s. thus , We found that , There will be no problems at the network connection level , that , What is the problem ？ Back to the Journal , The log has detailed error stack information , Is it possible to dig out some useful information from here ？

2.2  Problem recurrence

In question 1 In the Journal of , You can see that the logic here is set operation , stay spring-data-redis Of template The operation finally came to RedissonConnection Of write operation , Then is sync Blocking waits for the actual write result , that write Whether there is any abnormality in the stage , We tried to find more detailed logs ：

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


This log is more detailed , You can see that there is a throw NullPointerException, The specific place thrown out is redisson Of CommandEncoder, That makes a lot of sense . meanwhile , The reason why we found this anomaly is com.cmcc.hy.plus.biz.auth.JwtAuthenticationTokenFilter.doFilterInternal(JwtAuthenticationTokenFilter.java:150), In this line , We really found one of the systems bug, It is possible to use redisTemplate set null The situation of , therefore , We are IDE This error is simulated in , Discovery and use are based on redisson Of redisTemplate set null There will be CommandEncoder Of NullPointerException, Stack information is the same , Here we find that things seem to be getting clearer . however , The above question 1 And questions 2 How did it come about , Like and NullPointerException It's a completely different problem , Is there any connection between the two ？ Based on this , We have done more analysis on logs ,

After analysis, an interesting phenomenon was found , stay CommandEncoder Of NullPointerException Around , There will be either problems 1 Or the question 2 Error of , There are strong rules

. So is it CommandEncoder NullPointerException Other mistakes have spread ？ Coincidentally, , We're here IDE It's a recurring problem , In the verification of CommandEncoder NullPointerException when , The test case is not closed , stay 30s after , There is Ping abnormal ：

[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)


after , We narrowed down ping Interval of , For better observation , The result is very gratifying , In the use of redisTemplate set null when , appear CommandEncoder NullPointerException  after , It's bound to happen ping abnormal , Come here , It's quite a feeling of another village ！ problem 2 ping The timeout has been repeated , It turns out that it's not the reason for network connection , So the question 1  Write timeout , Is it caused by the same problem ？ According to this idea , Next, the method of recurrence is very simple , stay redisTemplate set null Then write a normal data , The result is a write timeout （ No more blog posts here ）, And must appear ！ And errors will always be reported in subsequent write and read operations , That is to say, the subsequent operations of this connection will always make mistakes , Until ping abnormal .ping The operation after the exception will no longer report an error , This also explains why the production environment will not always report errors , as for ping The reason why the error will not continue after the exception is PingConnectionHandler（ Regularly send ping The processor of instructions ） Will connect the wrong connection close,  The number of the following code 18 That's ok ：

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);


meanwhile ,ConnectionWatchdog Will try to reconnect （ Reconnection here refers to RedisConnection, Not the original tcp Connect ）：

 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();
 }


After reconnection , Will register a new channel, And use the new RedisConnection Carry out subsequent operations . Now that the problem has been repeated and a simple analysis based on this , So it's actually relatively simple to solve this problem , In our application code set null bug First make a layer of judgment , Can avoid the whole redisson The spread of the problem . however , I can't help asking , Why use jedis I didn't have this problem when I was young ？ because jedis When executing orders, treat all key、value Non null verification has been carried out , and redisson No, ！ Here are jedis Of set Code ：

Here are redisson Of set Code ：

It is a pity that ,redisson As a relatively mature open source project , There is no basic non null verification , And there is abnormal diffusion when problems occur . Come here , In fact, we have been able to solve the problem of production , At least it can ensure that there will be no more write timeout or ping Overtime , however , Please “ You know what you're doing and you know what you're doing ” The purpose of , We can't help but ask , What's the reason ,redisson There is abnormal diffusion ？

2.3  Source code analysis

Let's see redisson set when write Content in method ：

<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);
 }


This is an asynchronous to synchronous process ,

executorService.writeAsync

Asynchronous execution ,

sync

Blocking waiting for results . In this method

RedisCommand

Encapsulates the redis The order of ,

params

Is the parameter of the command . stay set null In the process of , From the previous log, it can be analyzed that

writeAsync

There's a problem in the process , Stack information indicates

CommandEncoder

Null pointer thrown ,

CommandEncoder

The function of is to request redis Instructions are encoded , It's a

MessageToByteEncoder

. Its coding method is as follows ：

 @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;
 }
 }


In the above code No 18 Yes

encode

In the method , Code the parameters in detail ,null This causes a null pointer exception to be thrown here , This exception is also caught at the end of this method

msg.tryFailure

End the calling process and throw the exception out , And finally encapsulate and transform the exception in the outer layer , This is in line with set null Exception stack information of . that , How does it affect the following operations ？ We use the following code to test ：

 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);
 }


The logic of the code is simple , Use StringRedisTemplate Write... First null value , Then write a normal value , Observe log. In the writing null When the value of , The result is the previous stack information , When writing the normal value , The error log is as follows ：

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


From the surface of the log , It's really overtime , First sentence “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. ” It means more than 3000ms No response yet ,3000ms yes redisson Response timeout for , So where did this come from ？ In our previous analysis ,redisson The write operation of is an asynchronous to synchronous process , Used sync Method blocking wait future Result . Since it is an asynchronous process , How does it control the timeout , The answer is

org.redisson.command.RedisExecutor#scheduleResponseTimeout

Method , This method will perform a scheduled task , The task is 3000ms（ Configurable ） After performing , The content of the task is to set the operation result to timeout , in other words , If 3000ms This task has not been cancel fall , Will throw the timeout exception . The core logic is this piece of code ：

 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);


You can see ,timeoutResponseTask We have assembled RedisResponseTimeoutException abnormal .

scheduleResponseTimeout

Where is the method called ？ From the source code, we can see that there is only one place to call this method , This place is

org.redisson.command.RedisExecutor#checkWriteFuture

,

checkWriteFuture

The function of is to check the result of the write request , If the writing is successful , This method will be called , As follows ：

 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);
 }
 });
 });


In the code above, No 15 That's ok , indicate

writeFuture

There is one Listener, stay write Check when the operation is completed

checkWriteFuture

. in other words , stay

scheduleResponseTimeout

Before , The actual request has been sent , that redis Did the server receive it ？ Use redis-cli Of monitor Function to view the request received by the server , You can really see the write request ：

You can see from the screenshot that the operation is SET,key yes test-normal-write, And redis The server did not receive SET test-null Instructions , because redisson stay

CommandEncoder

The stage has thrown a null pointer . from redis On the server side , Yes SET Operation processing is also very fast , Is the problem at the end of response processing ？ Let's take a look at redisson Processing request / What did you do in response , For details, please refer to

org.redisson.client.handler.RedisChannelInitializer#initChannel

Method , The code is as follows ：

 @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);
 }


You can see many familiar figures in the code , such as

pingConnectionHandler

、

CommandEncoder

、

connectionWatchdog

. From the above code , We can simply draw the input and output pipeline, Output （ request redis） Of pipieline as follows ：

ErrorsLoggingHandler -> CommandsQueue -> CommandBatchEncoder -> CommandEncoder


Input （ Respond to redis, It also includes establishing connections ） Of pipeline as follows ：

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


On the output request link , According to our analysis ,set null At the time

CommandEncoder

Throw an exception , Interrupted the request , stay set When the value is normal, the link is normal . On the input response chain , The main thing is

CommandDecoder

, Others are either processing logs , Or handle connection events , Here we focus on the analysis of

CommandDecoder

, Decoder . The first step of decoding is very important , It is to take out the operation command of the corresponding request ,redisson That's what it does ：

 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;
 }


It is from channel One of them queue, And then from queue in peek It's out

QueueCommandHolder

Respond as the current command to process . Since we can start from queue To take , When is that inserted queue What about , We can see in the request pipiline in , There is one

CommandsQueue

, It is here to put the order into queue Inside .

 @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);
 }
 }


here , We have a general idea of queue Correspondence between write and fetch , because peek It won't be right queue Do the data in remove operation , So there must be a place to queue Data launch in ,redisson The method of is to launch after decoding ,decode Then the following methods will be called ：

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


So that's the analysis , Our problem has basically been solved , In the case stringRedisTemplate set null after , Because in

CommandEncode

Stage threw a null pointer exception , As a result, the request was not sent , Then there will definitely be no

CommandDecoder

Stage , according to pipeline The order of ,

CommandsQueue

Is in

CommandEncoder

Before execution , It also means that queue It's stuffed with set null（ Refers to the instruction 1） Request instructions , There is no decoding phase to remove it from queue Launched in , This leads to the next set Normal value （ Instructions 2） When ordered by , The request was sent to redis,redis Also responded , But in the decoding stage , The extracted operation instruction is the last request （ Instructions 1） Of , So as to decode the exception , and , Because what is taken out at this time is the instruction of the first operation （ Instructions 1）, Second order （ Instructions 2） Still waiting for the next time from queue Remove and dispose of （promise.tryFailure）, Which leads to normal set（ Instructions 2） timeout . Since then , All subsequent requests will have errors , Because it was taken out in the decoding stage

QueueCommand

Always the last request , until

PinConnectionHandler

error , And disconnect , stay

ConnectionWatchDog

Reset the whole channel The data of .redisson As a mature open source framework , To have this bug In fact, it is very inappropriate , There are two solutions ：

• and jedis equally , stay set Wait for the pre emptive check before the operation ;

• stay
  CommandEncoder
  Of encode When an exception is thrown , Use final Statement will queue Medium
  QueueCommandHolder
  Introduction .

Of course , It is more inclined to plan 1.

3. summary

Based on the analysis of redisson Why the abnormal spread process , The process of actual experience is far more complicated than that in the text . One is redisson The log at the time of error is misleading , The first reaction to seeing the error log , Or there is a network error , Or redis Server error , After a long time of analysis, the network and redis Why , So we can go to the analysis redisson Its own implementation mechanism . in addition , Based on the analysis of redisson In the process of , The initial assumption was that the connection was closed during the request phase , But there is no release handle or reference , It also took a long time . During the analysis , Also printed many TRACE journal , This also helps eliminate many wrong directions . To make a long story short , Analyzing problems is a time-consuming process , It is also a process of continuous learning and progress , In the process , I'm familiar redisson, I'm familiar netty, It also provides a good reference for our own application code in the future .