io.lettuce.core.RedisCommandTimeoutException: Command timed out #1092

LakshmikanthQuickRide · 2019-07-30T05:39:20Z

Bug Report

Current Behavior

Stack trace

io.lettuce.core.RedisCommandTimeoutException: Command timed out after 10 second(s) at io.lettuce.core.ExceptionFactory.createTimeoutException(ExceptionFactory.java:51) ~[lettuce-core-5.1.6.RELEASE.jar:?] at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:114) ~[lettuce-core-5.1.6.RELEASE.jar:?] at io.lettuce.core.cluster.ClusterFutureSyncInvocationHandler.handleInvocation(ClusterFutureSyncInvocationHandler.java:123) ~[lettuce-core-5.1.6.RELEASE.jar:?] at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80) ~[lettuce-core-5.1.6.RELEASE.jar:?] at com.sun.proxy.$Proxy72.get(Unknown Source) ~[?:?] at sun.reflect.GeneratedMethodAccessor138.invoke(Unknown Source) ~[?:?] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_212] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_212] at io.lettuce.core.support.ConnectionWrapping$DelegateCloseToConnectionInvocationHandler.handleInvocation(ConnectionWrapping.java:191) ~[lettuce-core-5.1.6.RELEASE.jar:?] at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80) ~[lettuce-core-5.1.6.RELEASE.jar:?] at com.sun.proxy.$Proxy72.get(Unknown Source) ~[?:?] ```java // your stack trace here; ```

Input Code

public StatefulRedisClusterConnection<String, String> getRedisClient() {
		log.debug("getRedisClient()");
		if (pool == null) {
			synchronized (this) {
				pool = initializeConnectionPool();
			}
		}
		try {
			return pool.borrowObject();
		} catch (Exception e) {
			log.error("getting pool connection failed",e);
		}
		return null;
	}
	
	public GenericObjectPool<StatefulRedisClusterConnection<String, String>> initializeConnectionPool() {
		RedisClusterClient clusterClient = RedisClusterClient.create(new RedisURI(clusterUrl, clusterPort,Duration.ofMillis(10000)));
		ClusterTopologyRefreshOptions topologyRefreshOptions = ClusterTopologyRefreshOptions.builder()
			      .enableAllAdaptiveRefreshTriggers()
			      .refreshTriggersReconnectAttempts(30)
			      .build();
		clusterClient.setOptions(ClusterClientOptions.builder()
                .topologyRefreshOptions(topologyRefreshOptions)
                .build());
		pool = ConnectionPoolSupport.createGenericObjectPool(() -> clusterClient.connect(), getLettucePoolConfig());
		return pool;
	}

private GenericObjectPoolConfig getLettucePoolConfig() {
		GenericObjectPoolConfig poolConfig = new GenericObjectPoolConfig();
		poolConfig.setMaxTotal(256);
		poolConfig.setBlockWhenExhausted(true);
		poolConfig.setMaxWaitMillis(10000);
		poolConfig.setMaxIdle(100);
		poolConfig.setMinIdle(50);
		poolConfig.setTestOnBorrow(false);
		poolConfig.setTestWhileIdle(true);
		return poolConfig;
	}

Expected behavior/code

Environment

Lettuce version(s): 5.1.6-Release
Redis version: 5.0.4

Possible Solution

Additional context

mp911de · 2019-07-30T08:33:59Z

Please learn how to properly format code and logs.

The code does not contain any obvious issues. Please grab a thread dump once the issue occurs the next time. Maybe it's related to #1086.

LakshmikanthQuickRide · 2019-07-30T10:10:07Z

@mp911de

Thanks for the update , We have seen lot of threads are waiting at LockSupport.parkNanos , May we know when this version made public or any beta version available to verify the issue is fixed

"http-bio-8080-exec-80" #703 daemon prio=5 os_prio=0 tid=0x00007f3a4400e800 nid=0x1227 waiting on condition [0x00007f393d2d3000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00007f3fc846a088> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
	at io.lettuce.core.cluster.PipelinedRedisFuture.await(PipelinedRedisFuture.java:79)
	at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:112)
	at io.lettuce.core.cluster.ClusterFutureSyncInvocationHandler.handleInvocation(ClusterFutureSyncInvocationHandler.java:123)
	at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
	at com.sun.proxy.$Proxy72.mget(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor171.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at io.lettuce.core.support.ConnectionWrapping$DelegateCloseToConnectionInvocationHandler.handleInvocation(ConnectionWrapping.java:191)
	at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
	at com.sun.proxy.$Proxy72.mget(Unknown Source)

mp911de · 2019-07-30T10:13:13Z

The mentioned scenario is a regular one. The synchronous facade awaits command completion. Do you see other ones that are blocked, too? (Other ones than ClusterFutureSyncInvocationHandler).

LakshmikanthQuickRide · 2019-07-30T11:45:18Z

@mp911de

"lettuce-nioEventLoop-7-7" #219 daemon prio=5 os_prio=0 tid=0x00007f3ae016e000 nid=0x1004 waiting for monitor entry [0x00007f39601e7000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:204)
	- waiting to lock <0x00007f3bffe27c18> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:252)
	at io.netty.util.internal.logging.Slf4JLogger.debug(Slf4JLogger.java:81)
	at io.lettuce.core.protocol.RedisStateMachine.decode(RedisStateMachine.java:190)
	at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:708)
	at io.lettuce.core.protocol.CommandHandler.decode0(CommandHandler.java:672)
	at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:667)
	at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:587)
	at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:556)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:146)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)

"lettuce-nioEventLoop-7-3" #214 daemon prio=5 os_prio=0 tid=0x00007f3ad8003800 nid=0x1003 waiting for monitor entry [0x00007f3960268000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:204)
	- waiting to lock <0x00007f3bffe27c18> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:252)
	at io.netty.util.internal.logging.Slf4JLogger.debug(Slf4JLogger.java:81)
	at io.lettuce.core.protocol.CommandEncoder.encode(CommandEncoder.java:99)
	at io.lettuce.core.protocol.CommandEncoder.encode(CommandEncoder.java:75)
	at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:107)
	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.lettuce.core.protocol.CommandHandler.writeSingleCommand(CommandHandler.java:414)
	at io.lettuce.core.protocol.CommandHandler.write(CommandHandler.java:345)
	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:463)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)

mp911de · 2019-07-30T11:54:21Z

Thanks a lot. This is likely the cause for timeouts that for some reason Log4j blocks the I/O threads.

mp911de · 2019-07-30T12:07:43Z

May I close this ticket or is there anything else I can assist you with?

LakshmikanthQuickRide · 2019-07-30T12:30:01Z

@mp911de
How can we disable debug logs for lettuce client and log only warnings or errors

mp911de · 2019-07-30T12:46:15Z

Make sure your Log4jLoggerAdapter properly considers isDebugEnabled() flags. Lettuce checks on startup whether debug logging is enabled. If it's disabled, then Lettuce skips logging calls (see https://github.com/lettuce-io/lettuce-core/blob/master/src/main/java/io/lettuce/core/protocol/CommandEncoder.java#L39-L98).

Logging category for Lettuce is io.lettuce.core.

LakshmikanthQuickRide added the type: bug A general bug label Jul 30, 2019

mp911de added the status: waiting-for-feedback We need additional information before we can continue label Jul 30, 2019

mp911de added for: external-project For an external project and not something we can fix status: invalid An issue that we don't feel is valid and removed status: waiting-for-feedback We need additional information before we can continue type: bug A general bug labels Jul 30, 2019

mp911de closed this as completed Jul 30, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

io.lettuce.core.RedisCommandTimeoutException: Command timed out #1092

io.lettuce.core.RedisCommandTimeoutException: Command timed out #1092

LakshmikanthQuickRide commented Jul 30, 2019 •

edited

Loading

mp911de commented Jul 30, 2019

LakshmikanthQuickRide commented Jul 30, 2019 •

edited

Loading

mp911de commented Jul 30, 2019

LakshmikanthQuickRide commented Jul 30, 2019

mp911de commented Jul 30, 2019

mp911de commented Jul 30, 2019

LakshmikanthQuickRide commented Jul 30, 2019

mp911de commented Jul 30, 2019

io.lettuce.core.RedisCommandTimeoutException: Command timed out #1092

io.lettuce.core.RedisCommandTimeoutException: Command timed out #1092

Comments

LakshmikanthQuickRide commented Jul 30, 2019 • edited Loading

Bug Report

Current Behavior

Input Code

Expected behavior/code

Environment

Possible Solution

Additional context

mp911de commented Jul 30, 2019

LakshmikanthQuickRide commented Jul 30, 2019 • edited Loading

mp911de commented Jul 30, 2019

LakshmikanthQuickRide commented Jul 30, 2019

mp911de commented Jul 30, 2019

mp911de commented Jul 30, 2019

LakshmikanthQuickRide commented Jul 30, 2019

mp911de commented Jul 30, 2019

LakshmikanthQuickRide commented Jul 30, 2019 •

edited

Loading

LakshmikanthQuickRide commented Jul 30, 2019 •

edited

Loading