weixin_39730587
weixin_39730587
2020-11-27 23:05

With Zipkin, exception during startup trying to fetch endpoint prior to registration

I"m seeing an exception in the logs during application startup. It's logged at the WARN level and the application does start and work properly.

It looks like part of Zipkin initialization (in autoconfig) is trying to determine the current services endpoint info (host/port, I assume) by looking the service up in the service registry (in my case, Consul). However, the service doesn't register itself with Consul until later in the boot up process so it cannot find itself in Consul. The code then falls back to using information from the local properties files, logs the warning and moves on.

Is there any way move Zipkin initialization so that it occurs after service registration?


2016-03-08 11:30:46.115 [session=,request=,trace=,span=, export=,] [           main] [WARN] o.s.c.s.z.FallbackHavingEndpointLocator : Exception occurred while trying to fetch the Zipkin process endpoint. Falling back to server properties endpoint locator.
java.lang.IllegalStateException: Unable to locate service in consul agent: api-gateway-9999
    at org.springframework.cloud.consul.discovery.ConsulDiscoveryClient.getLocalServiceInstance(ConsulDiscoveryClient.java:67) ~[spring-cloud-consul-discovery-1.0.0.M4.jar:1.0.0.M4]
    at org.springframework.cloud.sleuth.zipkin.DiscoveryClientEndpointLocator.local(DiscoveryClientEndpointLocator.java:43) ~[spring-cloud-sleuth-zipkin-1.0.0.BUILD-20160308.165913-370.jar:1.0.0.BUILD-SNAPSHOT]
    at org.springframework.cloud.sleuth.zipkin.FallbackHavingEndpointLocator.local(FallbackHavingEndpointLocator.java:32) ~[spring-cloud-sleuth-zipkin-1.0.0.BUILD-20160308.165913-370.jar:1.0.0.BUILD-SNAPSHOT]
    at org.springframework.cloud.sleuth.zipkin.ZipkinAutoConfiguration.sleuthTracer(ZipkinAutoConfiguration.java:68) [spring-cloud-sleuth-zipkin-1.0.0.BUILD-20160308.165913-370.jar:1.0.0.BUILD-SNAPSHOT]
    at org.springframework.cloud.sleuth.zipkin.ZipkinAutoConfiguration$$EnhancerBySpringCGLIB$$7ee28321.CGLIB$sleuthTracer$2(<generated>) [spring-cloud-sleuth-zipkin-1.0.0.BUILD-20160308.165913-370.jar:1.0.0.BUILD-SNAPSHOT]
    at org.springframework.cloud.sleuth.zipkin.ZipkinAutoConfiguration$$EnhancerBySpringCGLIB$$7ee28321$$FastClassBySpringCGLIB$$84e3604.invoke(<generated>) [spring-cloud-sleuth-zipkin-1.0.0.BUILD-20160308.165913-370.jar:1.0.0.BUILD-SNAPSHOT]
    at org.springframework.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:228) [spring-core-4.2.4.RELEASE.jar:4.2.4.RELEASE]
    at org.springframework.context.annotation.ConfigurationClassEnhancer$BeanMethodInterceptor.intercept(ConfigurationClassEnhancer.java:355) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.cloud.sleuth.zipkin.ZipkinAutoConfiguration$$EnhancerBySpringCGLIB$$7ee28321.sleuthTracer(<generated>) [spring-cloud-sleuth-zipkin-1.0.0.BUILD-20160308.165913-370.jar:1.0.0.BUILD-SNAPSHOT]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_60]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_60]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_60]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_60]
    at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:162) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:588) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateUsingFactoryMethod(AbstractAutowireCapableBeanFactory.java:1123) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1018) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:510) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:772) [spring-beans-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:839) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:538) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
    at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:118) [spring-boot-1.3.2.RELEASE.jar:1.3.2.RELEASE]
    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:766) [spring-boot-1.3.2.RELEASE.jar:1.3.2.RELEASE]
    at org.springframework.boot.SpringApplication.createAndRefreshContext(SpringApplication.java:361) [spring-boot-1.3.2.RELEASE.jar:1.3.2.RELEASE]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:307) [spring-boot-1.3.2.RELEASE.jar:1.3.2.RELEASE]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1191) [spring-boot-1.3.2.RELEASE.jar:1.3.2.RELEASE]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1180) [spring-boot-1.3.2.RELEASE.jar:1.3.2.RELEASE]
    at com.appdirect.appdirect.service.gateway.Application.main(Application.java:17) [classes/:na]
</generated></generated></generated>

该提问来源于开源项目:spring-cloud/spring-cloud-sleuth

  • 点赞
  • 写回答
  • 关注问题
  • 收藏
  • 复制链接分享
  • 邀请回答

13条回答

  • weixin_39730587 weixin_39730587 5月前

    Interesting... Two out of three of my services started with no errors in the logs. The thirds one has the a similar, but different, stack trace but it has moved later in the start process. It now shows up 20ms after I see the log message for Consul registration.

    Looks like it is now happening while instrumenting a request, probably the health check ping from Consul. So, there is some sort of race condition. Note in the stack trace that Consul registration happens on the main thread and the exception happens on request processing thread pool-2-thread-1.

    
    2016-03-08 14:10:59.246 [session=,request=,trace=,span=, export=,] [           main] [INFO] o.s.c.consul.discovery.ConsulLifecycle  : Registering service with consul: NewService{id='pong-service-port8004-8004', name='pong-service', tags=[], address='192.168.99.1', port=8004, check=Check{script='null', interval=10s, ttl=null, http=http://192.168.99.1:8004/health, timeout=null}}
    2016-03-08 14:10:59.267 [session=,request=,trace=c3b6b6b0b611989f,span=c3b6b6b0b611989f, export=,true] [pool-2-thread-1] [WARN] o.s.c.s.z.FallbackHavingEndpointLocator : Exception occurred while trying to fetch the Zipkin process endpoint. Falling back to server properties endpoint locator.
    java.lang.IllegalStateException: Unable to locate service in consul agent: pong-service-port8004-8004
        at org.springframework.cloud.consul.discovery.ConsulDiscoveryClient.getLocalServiceInstance(ConsulDiscoveryClient.java:67) ~[spring-cloud-consul-discovery-1.0.0.M4.jar:1.0.0.M4]
        at org.springframework.cloud.sleuth.zipkin.DiscoveryClientEndpointLocator.local(DiscoveryClientEndpointLocator.java:43) ~[spring-cloud-sleuth-zipkin-1.0.0.BUILD-SNAPSHOT.jar:1.0.0.BUILD-SNAPSHOT]
        at org.springframework.cloud.sleuth.zipkin.FallbackHavingEndpointLocator.endpoint(FallbackHavingEndpointLocator.java:45) [spring-cloud-sleuth-zipkin-1.0.0.BUILD-SNAPSHOT.jar:1.0.0.BUILD-SNAPSHOT]
        at org.springframework.cloud.sleuth.zipkin.FallbackHavingEndpointLocator.local(FallbackHavingEndpointLocator.java:35) [spring-cloud-sleuth-zipkin-1.0.0.BUILD-SNAPSHOT.jar:1.0.0.BUILD-SNAPSHOT]
        at org.springframework.cloud.sleuth.zipkin.ZipkinSpanListener.convert(ZipkinSpanListener.java:144) [spring-cloud-sleuth-zipkin-1.0.0.BUILD-SNAPSHOT.jar:1.0.0.BUILD-SNAPSHOT]
        at org.springframework.cloud.sleuth.zipkin.ZipkinSpanListener.release(ZipkinSpanListener.java:120) [spring-cloud-sleuth-zipkin-1.0.0.BUILD-SNAPSHOT.jar:1.0.0.BUILD-SNAPSHOT]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_60]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_60]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_60]
        at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_60]
        at org.springframework.context.event.ApplicationListenerMethodAdapter.doInvoke(ApplicationListenerMethodAdapter.java:227) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.context.event.ApplicationListenerMethodAdapter.processEvent(ApplicationListenerMethodAdapter.java:144) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.context.event.ApplicationListenerMethodAdapter.onApplicationEvent(ApplicationListenerMethodAdapter.java:106) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:163) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:136) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:381) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:335) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.cloud.sleuth.trace.DefaultTracer.close(DefaultTracer.java:131) [spring-cloud-sleuth-core-1.0.0.BUILD-SNAPSHOT.jar:1.0.0.BUILD-SNAPSHOT]
        at org.springframework.cloud.sleuth.instrument.scheduling.TraceSchedulingAspect.traceBackgroundThread(TraceSchedulingAspect.java:67) [spring-cloud-sleuth-core-1.0.0.BUILD-SNAPSHOT.jar:1.0.0.BUILD-SNAPSHOT]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_60]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_60]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_60]
        at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_60]
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:620) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:609) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:68) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655) [spring-aop-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.cloud.consul.discovery.ConsulCatalogWatch$$EnhancerBySpringCGLIB$$353374e3.catalogServicesWatch(<generated>) [spring-cloud-consul-discovery-1.0.0.M4.jar:1.0.0.M4]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_60]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_60]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_60]
        at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_60]
        at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) [spring-context-4.2.5.RELEASE.jar:4.2.5.RELEASE]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_60]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [na:1.8.0_60]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_60]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [na:1.8.0_60]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_60]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_60]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_60]
    </generated>
    点赞 评论 复制链接分享
  • weixin_39965881 weixin_39965881 5月前

    Hmm. Interesting. Can you share a sample project that I can take a look into?

    点赞 评论 复制链接分享
  • weixin_39730587 weixin_39730587 5月前

    Not easily since it's forked off a private repo. Let me see what I can do. I think there is a way to duplicate it.

    点赞 评论 复制链接分享
  • weixin_39730587 weixin_39730587 5月前

    I added you as a Collaborator on my repo. I hope you get an email with the repo info so I don't need to post it here. Let me know if you didn't get an email.

    点赞 评论 复制链接分享
  • weixin_39965881 weixin_39965881 5月前

    Yup I got some access - will check it out today

    点赞 评论 复制链接分享
  • weixin_39965881 weixin_39965881 5月前

    Can you join Gitter - https://gitter.im/spring-cloud/spring-cloud-sleuth cause I'd like to have a chat with you about this issue

    点赞 评论 复制链接分享
  • weixin_39965881 weixin_39965881 5月前

    I wonder what we can really do about this actually... Like you said a request came in and instrumentation took place. A span is ready to be sent to Zipkin. It needs an endpoint so either we block span sending until an event was emitted that the app got registered. But if that event never comes? So we would have to have a timeout...

    Another solution would be to update that value of Endpoint once an event that the app got registered was received. Then you could have a warning in the logs but only once. ATM you also have once but then the property based solution is used. In this case the next time the dependency based would be chosen.

    Another interesting matter is whether we shouldn't skip the /health endpoint.

    CC

    点赞 评论 复制链接分享
  • weixin_39517797 weixin_39517797 5月前

    I thought we already skip exporting /health traces (so yes, probably we should skip it)? I'm OK with any solution that a) doesn't crash the app, and b) sends the correct endpoint information for all spans as soon as it is known (and doesn't bother trying to fix the race).

    点赞 评论 复制链接分享
  • weixin_39965881 weixin_39965881 5月前

    So it seems that we skipped /health endpoint and now I've added it on this branch and re-run the apps - I can't see any errors in the logs. I think this is the best solution - let's defer endpoint location until the first usage and let's skip /health endpoint by default

    点赞 评论 复制链接分享
  • weixin_39730587 weixin_39730587 5月前

    I had already added /health to skipPattern using spring.sleuth.instrument.web.skipPattern so not sure that that part of your fix is actually going to help. Using the local endpoint definition until it can be read from Consul is a good solution, though.

    点赞 评论 复制链接分享
  • weixin_39965881 weixin_39965881 5月前

    Hmm the combination of both adding /health + deferring the local endpoint resolution worked for me. But maybe I'm lucky. Check if things in master are working fine. If not then we'll reopen this and think of some other solution

    点赞 评论 复制链接分享
  • weixin_39730587 weixin_39730587 5月前

    Looks good now. I'm not seeing the errors anymore.

    点赞 评论 复制链接分享
  • weixin_39965881 weixin_39965881 5月前

    H! Can you check out this branch: issues_#205_deferring_locating_endpoint , build Sleuth locally and check if it's working better?

    Here is the PR: https://github.com/spring-cloud/spring-cloud-sleuth/commit/6da7df1f60149297a14746552a867282126ef0d3

    点赞 评论 复制链接分享

相关推荐