spring-boot-starter-data-redis is 2.2.4 with spring-cloud Hoxton SR1. upgrade to spring-boot-2.2.4, the program stuck at start-up with the log
2020-02-12 10:14:59.891 [INFO ] [2964] - c.x.c.order.center.service.CacheService [ 198] : accessing redis now
2020-02-12 10:14:59.894 [DEBUG] [2964] - o.s.d.redis.core.RedisConnectionUtils [ 129] : Opening RedisConnection
2020-02-12 10:14:59.919 [DEBUG] [2964] - io.lettuce.core.RedisClient [ 264] : Trying to get a Redis connection for: RedisURI [host='localhost', port=6379]
2020-02-12 10:15:00.167 [INFO ] [2964] - io.lettuce.core.EpollProvider [ 68] : Starting without optional epoll library
2020-02-12 10:15:00.172 [INFO ] [2964] - io.lettuce.core.KqueueProvider [ 70] : Starting without optional kqueue library
2020-02-12 10:15:00.179 [DEBUG] [2964] - i.l.c.r.DefaultEventLoopGroupProvider [ 64] : Allocating executor io.netty.channel.nio.NioEventLoopGroup
2020-02-12 10:15:00.180 [DEBUG] [2964] - i.l.c.r.DefaultEventLoopGroupProvider [ 138] : Creating executor io.netty.channel.nio.NioEventLoopGroup
2020-02-12 10:15:00.180 [DEBUG] [2964] - i.n.channel.MultithreadEventLoopGroup [ 44] : -Dio.netty.eventLoopThreads: 16
2020-02-12 10:15:00.191 [DEBUG] [2964] - io.netty.channel.nio.NioEventLoop [ 106] : -Dio.netty.noKeySetOptimization: false
2020-02-12 10:15:00.192 [DEBUG] [2964] - io.netty.channel.nio.NioEventLoop [ 107] : -Dio.netty.selectorAutoRebuildThreshold: 512
2020-02-12 10:15:00.222 [DEBUG] [2964] - i.l.c.r.DefaultEventLoopGroupProvider [ 77] : Adding reference to io.netty.channel.nio.NioEventLoopGroup@3aac31b7, existing ref count 0
2020-02-12 10:15:00.257 [DEBUG] [2964] - io.lettuce.core.RedisClient [ 772] : Resolved SocketAddress localhost:6379 using RedisURI [host='localhost', port=6379]
2020-02-12 10:15:00.258 [DEBUG] [2964] - io.lettuce.core.RedisClient [ 304] : Connecting to Redis at localhost:6379
2020-02-12 10:15:00.268 [DEBUG] [2964] - io.netty.channel.DefaultChannelId [ 79] : -Dio.netty.processId: 2964 (auto-detected)
2020-02-12 10:15:00.271 [DEBUG] [2964] - io.netty.util.NetUtil [ 139] : -Djava.net.preferIPv4Stack: false
2020-02-12 10:15:00.271 [DEBUG] [2964] - io.netty.util.NetUtil [ 140] : -Djava.net.preferIPv6Addresses: false
2020-02-12 10:15:00.860 [DEBUG] [2964] - io.netty.util.NetUtil [ 224] : Loopback interface: lo (Software Loopback Interface 1, 127.0.0.1)
2020-02-12 10:15:00.862 [DEBUG] [2964] - io.netty.util.NetUtil [ 289] : Failed to get SOMAXCONN from sysctl and file \proc\sys\net\core\somaxconn. Default: 200
2020-02-12 10:15:01.578 [DEBUG] [2964] - io.netty.channel.DefaultChannelId [ 101] : -Dio.netty.machineId: 54:e1:ad:ff:fe:e5:39:71 (auto-detected)
2020-02-12 10:15:01.680 [DEBUG] [2964] - io.netty.buffer.ByteBufUtil [ 86] : -Dio.netty.allocator.type: pooled
2020-02-12 10:15:01.682 [DEBUG] [2964] - io.netty.buffer.ByteBufUtil [ 95] : -Dio.netty.threadLocalDirectBufferSize: 0
2020-02-12 10:15:01.683 [DEBUG] [2964] - io.netty.buffer.ByteBufUtil [ 98] : -Dio.netty.maxThreadLocalCharBufferSize: 16384
2020-02-12 10:15:01.801 [DEBUG] [2964] - io.netty.util.Recycler [ 97] : -Dio.netty.recycler.maxCapacityPerThread: 4096
2020-02-12 10:15:01.802 [DEBUG] [2964] - io.netty.util.Recycler [ 98] : -Dio.netty.recycler.maxSharedCapacityFactor: 2
2020-02-12 10:15:01.802 [DEBUG] [2964] - io.netty.util.Recycler [ 99] : -Dio.netty.recycler.linkCapacity: 16
2020-02-12 10:15:01.802 [DEBUG] [2964] - io.netty.util.Recycler [ 100] : -Dio.netty.recycler.ratio: 8
2020-02-12 10:15:01.865 [DEBUG] [2964] - io.netty.buffer.AbstractByteBuf [ 63] : -Dio.netty.buffer.checkAccessible: true
2020-02-12 10:15:01.866 [DEBUG] [2964] - io.netty.buffer.AbstractByteBuf [ 64] : -Dio.netty.buffer.checkBounds: true
2020-02-12 10:15:01.867 [DEBUG] [2964] - i.n.util.ResourceLeakDetectorFactory [ 195] : Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@667f21a1
2020-02-12 10:15:01.984 [DEBUG] [2964] - io.lettuce.core.protocol.CommandHandler [ 162] : [channel=0x44d72740, [id: 0x74a61e27] (inactive), chid=0x1] channelRegistered()
2020-02-12 10:15:02.024 [DEBUG] [2964] - io.lettuce.core.protocol.CommandHandler [ 271] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, chid=0x1] channelActive()
2020-02-12 10:15:02.026 [DEBUG] [2964] - i.lettuce.core.protocol.DefaultEndpoint [ 371] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, epid=0x1] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
2020-02-12 10:15:02.026 [DEBUG] [2964] - i.lettuce.core.protocol.DefaultEndpoint [ 376] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, epid=0x1] activating endpoint
2020-02-12 10:15:02.026 [DEBUG] [2964] - i.lettuce.core.protocol.DefaultEndpoint [ 453] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, epid=0x1] flushCommands()
2020-02-12 10:15:02.027 [DEBUG] [2964] - i.lettuce.core.protocol.DefaultEndpoint [ 468] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, epid=0x1] flushCommands() Flushing 0 commands
2020-02-12 10:15:02.027 [DEBUG] [2964] - i.l.core.protocol.ConnectionWatchdog [ 167] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, last known addr=localhost/127.0.0.1:6379] channelActive()
2020-02-12 10:15:02.028 [DEBUG] [2964] - io.lettuce.core.protocol.CommandHandler [ 285] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, chid=0x1] channelActive() done
2020-02-12 10:15:02.029 [DEBUG] [2964] - io.lettuce.core.RedisClient [ 337] : Connecting to Redis at localhost:6379: Success
2020-02-12 10:15:02.049 [DEBUG] [2964] - io.lettuce.core.RedisChannelHandler [ 171] : dispatching command AsyncCommand [type=AUTH, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand]
2020-02-12 10:15:02.060 [DEBUG] [2964] - i.lettuce.core.protocol.DefaultEndpoint [ 339] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, epid=0x1] write() writeAndFlush command TracedCommand [type=AUTH, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand]
2020-02-12 10:15:02.062 [DEBUG] [2964] - io.lettuce.core.protocol.CommandHandler [ 349] : [channel=0x44d72740, /127.0.0.1:57898 -> localhost/127.0.0.1:6379, chid=0x1] write(ctx, TracedCommand [type=AUTH, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)
There is no exception thrown.
my code
log.info("accessing redis now");
ValueOperations<String, Boolean> valueOperations = redisTemplate.opsForValue();
Boolean redisValue =valueOperations.get("redisKey");
log.info("value at redis is:{}",redisValue);
Log accessing redis to get value is not output. When I downgrade to a lower version of spring-boot-2.1.12, it work fine. What's the problem with my code.
by the way,when i change the pool type from lettuce to jedis , it work fine too.
Comment From: snicoll
What's the problem with my code.
We can't really say with the info you've provided unfortunately. Given that it works when you change the connection pool, it might not be an issue in Spring Boot (cc @mp911de). To be sure, can you please share a small sample (zip or link to a github repo) that we can use to reproduce the issue?
Comment From: mp911de
We've seen a similar report today at spring-cloud/spring-cloud-sleuth#1557. The linked issue is related to tracing along with using Redis in @PostConstruct.
I don't think that this is a Spring Boot issue, but a reproducer will help us fully understand what's going on.
Comment From: Comven
We've seen a similar report today at spring-cloud/spring-cloud-sleuth#1557. The linked issue is related to tracing along with using Redis in
@PostConstruct.I don't think that this is a Spring Boot issue, but a reproducer will help us fully understand what's going on.
Maybe it's the same kind of problem. In my code, it happens in the afterPropertiesSet() method block
Comment From: snicoll
@Comven thanks for the feedback. Please share a small sample as requested above.
Comment From: Comven
@Comven thanks for the feedback. Please share a small sample as requested above.
Sorry, it's our company's project. I tried to write a small demo, but found that the demo was working normally, so I suspected that other components had an impact on it, but I haven't found it yet
Comment From: Comven
I use the jstack tool to get information like this
"lettuce-nioEventLoop-4-1" #116 daemon prio=5 os_prio=0 tid=0x0000000022f9a800 nid=0x5d8 waiting for monitor entry [0x00000000284dc000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:204)
- waiting to lock <0x00000006c3250c00> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:321)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202)
at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:409)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateUsingFactoryMethod(AbstractAutowireCapableBeanFactory.java:1338)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1177)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:557)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:517)
at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$1(AbstractBeanFactory.java:359)
at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$758/1762049551.getObject(Unknown Source)
at org.springframework.cloud.context.scope.GenericScope$BeanLifecycleWrapper.getBean(GenericScope.java:389)
- locked <0x00000006c37bd6a0> (a java.lang.String)
at org.springframework.cloud.context.scope.GenericScope.get(GenericScope.java:186)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:356)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202)
at org.springframework.aop.target.SimpleBeanTargetSource.getTarget(SimpleBeanTargetSource.java:35)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
at brave.sampler.Sampler$$EnhancerBySpringCGLIB$$26eb01bb.isSampled(<generated>)
at brave.Tracer.decorateContext(Tracer.java:268)
at brave.Tracer.newRootContext(Tracer.java:204)
at brave.Tracer.newTrace(Tracer.java:151)
at brave.Tracer.nextSpan(Tracer.java:470)
at io.lettuce.core.tracing.BraveTracing$BraveTracer.nextSpan(BraveTracing.java:259)
at io.lettuce.core.tracing.BraveTracing$BraveTracer.nextSpan(BraveTracing.java:266)
at io.lettuce.core.protocol.CommandHandler.writeSingleCommand(CommandHandler.java:392)
at io.lettuce.core.protocol.CommandHandler.write(CommandHandler.java:353)
at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:715)
at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:762)
at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:788)
at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:756)
at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:806)
at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1025)
at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:294)
at io.lettuce.core.protocol.DefaultEndpoint.channelWriteAndFlush(DefaultEndpoint.java:342)
at io.lettuce.core.protocol.DefaultEndpoint.writeToChannelAndFlush(DefaultEndpoint.java:282)
at io.lettuce.core.protocol.DefaultEndpoint.write(DefaultEndpoint.java:142)
at io.lettuce.core.protocol.CommandExpiryWriter.write(CommandExpiryWriter.java:112)
at io.lettuce.core.RedisChannelHandler.dispatch(RedisChannelHandler.java:184)
at io.lettuce.core.StatefulRedisConnectionImpl.dispatch(StatefulRedisConnectionImpl.java:152)
at io.lettuce.core.AbstractRedisAsyncCommands.dispatch(AbstractRedisAsyncCommands.java:467)
at io.lettuce.core.AbstractRedisAsyncCommands.dispatch(AbstractRedisAsyncCommands.java:454)
at io.lettuce.core.RedisClient.lambda$connectStatefulAsync$2(RedisClient.java:302)
at io.lettuce.core.RedisClient$$Lambda$965/1970983463.apply(Unknown Source)
at java.util.concurrent.CompletableFuture.uniCompose(CompletableFuture.java:952)
at java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:926)
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
at io.lettuce.core.AbstractRedisClient.lambda$null$3(AbstractRedisClient.java:340)
at io.lettuce.core.AbstractRedisClient$$Lambda$970/453932096.accept(Unknown Source)
at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760)
at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736)
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
at io.lettuce.core.PlainChannelInitializer$1.userEventTriggered(PlainChannelInitializer.java:93)
at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:344)
at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:330)
at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:322)
at io.netty.channel.DefaultChannelPipeline$HeadContext.userEventTriggered(DefaultChannelPipeline.java:1428)
at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:344)
at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:330)
at io.netty.channel.DefaultChannelPipeline.fireUserEventTriggered(DefaultChannelPipeline.java:913)
at io.lettuce.core.protocol.CommandHandler.lambda$channelActive$0(CommandHandler.java:281)
at io.lettuce.core.protocol.CommandHandler$$Lambda$974/911607826.run(Unknown Source)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.PromiseTask.run(PromiseTask.java:106)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
Comment From: mp911de
Thanks for looking into jstack. I can confirm that this issue is a duplicate of the earlier mentioned Spring Cloud issue. We can close this ticket here and continue over at the Spring Cloud one.
Comment From: Comven
OK, TKS