spring lettuce startup get blocks when including spring-cloud-starter-zipkin #1557

WEIZIBIN · 2020-02-12T03:33:08Z

Describe the bug
Spring redis get connection block when include spring-cloud-starter-zipkin.

2020-02-12 11:31:27.025 INFO [,,,] 25158 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.sleuth.zipkin2.sender.ZipkinRestTemplateSenderConfiguration' of type [org.springframework.cloud.sleuth.zipkin2.sender.ZipkinRestTemplateSenderConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-02-12 11:31:27.027 INFO [,,,] 25158 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'zipkinRestTemplateCustomizer' of type [org.springframework.cloud.sleuth.zipkin2.DefaultZipkinRestTemplateCustomizer] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-02-12 11:31:27.038 INFO [,,,] 25158 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'zipkinSender' of type [org.springframework.cloud.sleuth.zipkin2.sender.RestTemplateSender] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-02-12 11:31:27.075 WARN [,,,] 25158 --- [ main] o.s.c.s.zipkin2.ZipkinAutoConfiguration : Check result of the [AsyncReporter{org.springframework.cloud.sleuth.zipkin2.sender.RestTemplateSender@1dba4e06}] contains an error [CheckResult{ok=false, error=org.springframework.web.client.ResourceAccessException: I/O error on POST request for "http://localhost:9411/api/v2/spans": Connection refused (Connection refused); nested exception is java.net.ConnectException: Connection refused (Connection refused)}]
2020-02-12 11:31:27.076 INFO [,,,] 25158 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'zipkinReporter' of type [zipkin2.reporter.AsyncReporter$BoundedAsyncReporter] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-02-12 11:31:27.086 INFO [,,,] 25158 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'tracing' of type [brave.Tracing$Default] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-02-12 11:31:27.089 INFO [,,,] 25158 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'spring.sleuth.redis-org.springframework.cloud.sleuth.instrument.redis.TraceRedisProperties' of type [org.springframework.cloud.sleuth.instrument.redis.TraceRedisProperties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-02-12 11:31:27.454 INFO [,,,] 25158 --- [ main] io.lettuce.core.EpollProvider : Starting without optional epoll library
2020-02-12 11:31:27.455 INFO [,,,] 25158 --- [ main] io.lettuce.core.KqueueProvider : Starting without optional kqueue library

If pom.xml not include spring-cloud-starter-zipkin, then redis success get connection.

Sample
Sample Project
block in io.lettuce.core.AbstractRedisClient#getConnection()

marcingrzejszczak · 2020-02-12T07:29:09Z

@mp911de have you seen such a problem before?

mp911de · 2020-02-12T07:31:36Z

Do you mean Connection refused (Connection refused); nested exception is java.net.ConnectException: Connection refused (Connection refused)}] or the bean-postprocesors?

marcingrzejszczak · 2020-02-12T07:32:55Z

From what I understand this the problem block in io.lettuce.core.AbstractRedisClient#getConnection() . All the entries in the logs are not related to the issue as far as I understand.

BTW @WEIZIBIN you know that we have Hoxton.SR1 ?

mp911de · 2020-02-12T08:06:55Z

The application startup gets stuck (blocked). There are two things that come together:

Calling Redis in @PostConstruct which awaits command completion since it's a blocking call.
Background initialization of Brave in combination with AOP. The I/O thread gets blocked by Brave/AOP by the Spring Framework initialization lock.

Since the context is not fully started, the startup lock prevents progress each time a thread different than main tries to obtain a Spring bean. Here's the stack trace of the blocked thread:

"lettuce-nioEventLoop-4-1@6556" daemon prio=5 tid=0x26 nid=NA waiting for monitor entry
  java.lang.Thread.State: BLOCKED
	 waiting for main@1 to release lock on <0x1c0c> (a java.util.concurrent.ConcurrentHashMap)
	  at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:205)
	  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$523.791402620.getObject(Unknown Source:-1)
	  at org.springframework.cloud.context.scope.GenericScope$BeanLifecycleWrapper.getBean(GenericScope.java:389)
	  - locked <0x1c45> (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$$79d02789.isSampled(<generated>:-1)
	  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:716)
	  at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:708)
	  at io.netty.channel.AbstractChannelHandlerContext.access$1700(AbstractChannelHandlerContext.java:56)
	  at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:1102)
	  at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1149)
	  at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:1073)
	  at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163)
	  at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:-1)
	  at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:510)
	  at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:518)
	  at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050)
	  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:830)

WEIZIBIN · 2020-02-12T09:34:14Z

Thanks, I have reached the same conclusion after using the jstack command. Has this issue been resolved now? @mp911de

WEIZIBIN · 2020-02-12T09:36:25Z

I upgraded to Hoxton.SR1 and still have the same problem. @marcingrzejszczak

Comven · 2020-02-12T09:42:09Z

I upgraded to Hoxton.SR1 and still have the same problem. @marcingrzejszczak

spring-boot-2.2.4+spring-cloud Hoxton.SR1 have the same problem

WEIZIBIN · 2020-02-12T10:04:35Z

My current solution is to execute it before redis executes the command.
tracing.tracer().nextSpan ();
Then [Main] thread initializes Tracer first, so when redis executes the command, the IO thread will not block at getSingleton().

Is there a better solution?

marcingrzejszczak · 2020-02-19T08:53:17Z

Hey @WEIZIBIN , this is an extremely interesting case. I had a chat with @mp911de and we have the following conclusions:

The problem is here in SamplerAutoConfiguration in usage of RefreshScope.

@Configuration(proxyBeanMethods = false)
	@ConditionalOnBean(
			type = "org.springframework.cloud.context.scope.refresh.RefreshScope")
	protected static class RefreshScopedSamplerConfiguration {

		@Bean
		@RefreshScope
		@ConditionalOnMissingBean
		public Sampler defaultTraceSampler(SamplerProperties config) {
			return samplerFromProps(config);
		}

	}

Since we're using RefreshScope around the sampler bean and according to @mp911de the proxy is not lazy, we have an issue that there's a lock on the bean.

In order for you to have a workaround, you can use what you mentioned or create your own sampler bean e.g. using the always sampler if that's ok for you.

@Bean
	public Sampler mySampler() {
		return Sampler.ALWAYS_SAMPLE;
	}

Now I guess we'd need to chat with @dsyer and @spencergibb (cc @ryanjbaxter, @OlgaMaciaszek ) about those refresh scope proxies and their usage in @PostConstruct annotated methods.

Comven · 2020-04-24T12:15:07Z

Is the bug fixed?

marcingrzejszczak · 2020-07-29T16:21:37Z

Pinging @dsyer and @spencergibb (cc @ryanjbaxter, @OlgaMaciaszek ) about those refresh scope proxies and their usage in @PostConstruct annotated methods. Any ideas how to fix this?

marcingrzejszczak · 2020-08-07T11:58:32Z

The suggested solution to this problem is

By default samplers will work with the refresh scope mechanism. That means that you can change the sampling properties at runtime, refresh the application and the changes will be reflected. However, sometimes the fact of creating a proxy around samplers and calling it from too early (from @PostConstruct annotated method) may lead to dead locks. In such a case either create a sampler bean explicitly, or set the property spring.sleuth.sampler.refresh.enabled to false to disable the refresh scope support.

Best solution would be not to use the redis stuff from @PostConstruct. If you have to do it, just set the sampler bean explicitly or wait for 3.0.0 release and set the spring.sleuth.sampler.refresh.enabled to false

elvizlai · 2020-08-14T09:50:29Z

+1

sharath29 · 2021-06-19T10:41:27Z

I am getting similar error when trying to connect to redis from spring boot application, from the private static final StatefulRedisConnection<String, String> connection = redisClientNew.connect(); line.

@Component
@RequiredArgsConstructor
public class RedisCacheClient {

    private static final SpectraLogger logger = OlympusSpectra.getLogger(RedisCacheClient.class);
    private static final RedisURI redisURI = RedisURI.builder().withSentinel("localhost", 26379).withSentinelMasterId("mymaster").build();
    private static final RedisClient redisClientNew = RedisClient.create(redisURI);
    private static final StatefulRedisConnection<String, String> connection = redisClientNew.connect();
    private static final RedisAsyncCommands<String, String> async = connection.async();
    private static final Gson gson = new Gson();
    private static final Long KEY_EXIST = 1L;

Spring boot console log stuck after these two messages:

2021-06-19 16:02:44,704 8253 [main] INFO  [i.l.c.EpollProvider] {{clusterName,default}{appResourceId,ss@dev}} - Starting without optional epoll library 
2021-06-19 16:02:44,707 8256 [main] INFO  [i.l.c.KqueueProvider] {{clusterName,default}{appResourceId,ss@dev}} - Starting without optional kqueue library

The error is coming from io.lettuce.core.AbstractRedisClient return connectionFuture.get(); inside the try block.

    protected <T> T getConnection(ConnectionFuture<T> connectionFuture) {
        try {
            return connectionFuture.get();
        } catch (InterruptedException var3) {
            Thread.currentThread().interrupt();
            throw RedisConnectionException.create(connectionFuture.getRemoteAddress(), var3);
        } catch (Exception var4) {
            if (var4 instanceof ExecutionException) {
                throw RedisConnectionException.create(connectionFuture.getRemoteAddress(), var4.getCause());
            } else {
                throw RedisConnectionException.create(connectionFuture.getRemoteAddress(), var4);
            }
        }
    }

Please let me know if this is the same issue and how can i proceed further.

pom.xml

    <dependency>
      <groupId>io.lettuce</groupId>
      <artifactId>lettuce-core</artifactId>
    </dependency>
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-data-redis</artifactId>
    </dependency>

marcingrzejszczak · 2021-06-19T11:28:32Z

You have not provided which version of cloud, boot and sleuth you're using. Please update to the latest versions and try again

sharath29 · 2021-06-19T11:40:37Z

You have not provided which version of cloud, boot and sleuth you're using. Please update to the latest versions and try again

I am not using these two in my project.

marcingrzejszczak · 2021-06-19T11:56:16Z

So why are you commenting on a sleuth lettuce integration issue in a sleuth project that depends on boot is you're neither using sleuth nor boot?

sharath29 · 2021-06-19T12:25:55Z

I have been stuck with this error and the only closest thing which i could find was this post, and the errors being faced here matches with mine since its coming from the exact same line in the lettuce module.

spencergibb · 2021-06-19T13:04:34Z

We can only help with spring cloud sleuth integration with lettuce. You'll need to find help elsewhere.

spring-projects-issues added the waiting-for-triage label Feb 12, 2020

marcingrzejszczak added waiting for feedback and removed waiting-for-triage labels Feb 12, 2020

spring-projects-issues added feedback-provided and removed waiting for feedback labels Feb 12, 2020

mp911de mentioned this issue Feb 12, 2020

spring-boot-starter-data-redis stuck at start-up spring-projects/spring-boot#20131

Closed

WEIZIBIN changed the title ~~spring redis get connection block when include spring-cloud-starter-zipkin~~ spring lettuce startup get blocks when including spring-cloud-starter-zipkin Feb 12, 2020

mp911de mentioned this issue Mar 27, 2020

spring boot2.1.11 upgrade to spring boot2.2.2 stucked when server setups redis/lettuce#1192

Closed

marcingrzejszczak added in progress and removed feedback-provided labels Jul 29, 2020

marcingrzejszczak added for team discussion enhancement and removed for team discussion in progress labels Aug 7, 2020

marcingrzejszczak added this to the 3.0.0-M4 milestone Aug 7, 2020

marcingrzejszczak closed this as completed in 9d0ee14 Aug 7, 2020

darshitpp mentioned this issue Nov 4, 2022

Redis won't connect if sleuth tracing is enabled spring-projects/spring-data-redis#2249

Closed

spring lettuce startup get blocks when including spring-cloud-starter-zipkin #1557

spring lettuce startup get blocks when including spring-cloud-starter-zipkin #1557

Comments

WEIZIBIN commented Feb 12, 2020

marcingrzejszczak commented Feb 12, 2020

Uh oh!

mp911de commented Feb 12, 2020

Uh oh!

marcingrzejszczak commented Feb 12, 2020

Uh oh!

mp911de commented Feb 12, 2020

Uh oh!

WEIZIBIN commented Feb 12, 2020

Uh oh!

WEIZIBIN commented Feb 12, 2020

Uh oh!

Comven commented Feb 12, 2020

Uh oh!

WEIZIBIN commented Feb 12, 2020

Uh oh!

marcingrzejszczak commented Feb 19, 2020

Uh oh!

Comven commented Apr 24, 2020

Uh oh!

marcingrzejszczak commented Jul 29, 2020

Uh oh!

marcingrzejszczak commented Aug 7, 2020

Uh oh!

elvizlai commented Aug 14, 2020

Uh oh!

sharath29 commented Jun 19, 2021

Uh oh!

marcingrzejszczak commented Jun 19, 2021

Uh oh!

sharath29 commented Jun 19, 2021

Uh oh!

marcingrzejszczak commented Jun 19, 2021

Uh oh!

sharath29 commented Jun 19, 2021

Uh oh!

spencergibb commented Jun 19, 2021

Uh oh!