spring-cloud-sleuth icon indicating copy to clipboard operation
spring-cloud-sleuth copied to clipboard

ZipkinAutoConfiguration executes the shutdown hook multiple times when using System.exit()

Open breiler opened this issue 3 years ago • 3 comments

Describe the bug When using Zipkin in a Spring Boot batch application the shutdown hook here is called multiple times causing Zipkin to throw an exception. Should the shutdown hook be replaced with a @PreDestroy method?

Exception:

Exception in thread "Thread-3" zipkin2.reporter.ClosedSenderException
	at zipkin2.reporter.AsyncReporter$BoundedAsyncReporter.flush(AsyncReporter.java:265)
	at org.springframework.cloud.sleuth.autoconfig.zipkin2.ZipkinAutoConfiguration$1.run(ZipkinAutoConfiguration.java:144)

Sample Example program:

@SpringBootApplication
@ConfigurationPropertiesScan
public class Application {

    public static void main(String[] args) {
        ConfigurableApplicationContext ctx = SpringApplication.run(Application.class, args);
        int exitCode = SpringApplication.exit(ctx, () -> 0);   // Shuts down spring boot and executes all shut down hooks.
        System.exit(exitCode); // Triggers the shutdown hook a second time in https://github.com/spring-cloud/spring-cloud-sleuth/blob/3.1.x/spring-cloud-sleuth-autoconfigure/src/main/java/org/springframework/cloud/sleuth/autoconfig/zipkin2/ZipkinAutoConfiguration.java#L141
    }
}

Versions

I am using:

  • spring-boot-2.7.3
  • spring-cloud-sleuth-autoconfigure-3.1.3
  • zipkin-reporter-2.16.3

breiler avatar Sep 05 '22 10:09 breiler

Are all shutdown hooks called twice or only this one (e.g.: what if you register your own)? Also, I'm not sure you need to do all this, System.exit should be enough since Spring should have it's own shutdown hook that closes the context and shuts down your app.

jonatan-ivanov avatar Sep 09 '22 19:09 jonatan-ivanov

Sorry, my mistake, the shutdown-hook seems to behave correctly and is only executed once. The System.exit was redundant since Spring seems to add an error code if the application encounters an error while executing a org.springframework.boot.CommandLineRunner which our batch implements.

So if I simplify our main application like this:

package com.xxx.mybatch;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.context.properties.ConfigurationPropertiesScan;
import org.springframework.context.ConfigurableApplicationContext;

@SpringBootApplication
@ConfigurationPropertiesScan
public class Application {

    public static void main(String[] args) {
        ConfigurableApplicationContext ctx = SpringApplication.run(Application.class, args);
        SpringApplication.exit(ctx, () -> 0);  // Still needed to shut down Spring once our CommandLineRunner is finished
    }
}

When the SpringApplication.exit is executed, the AsyncReporter is closed through what looks like an AutoClosable-handler given this call stack. So far so good.

close:337, AsyncReporter$BoundedAsyncReporter (zipkin2.reporter)
destroy:239, DisposableBeanAdapter (org.springframework.beans.factory.support)
destroyBean:587, DefaultSingletonBeanRegistry (org.springframework.beans.factory.support)
destroySingleton:559, DefaultSingletonBeanRegistry (org.springframework.beans.factory.support)
destroySingleton:1163, DefaultListableBeanFactory (org.springframework.beans.factory.support)
destroySingletons:520, DefaultSingletonBeanRegistry (org.springframework.beans.factory.support)
destroySingletons:1156, DefaultListableBeanFactory (org.springframework.beans.factory.support)
destroyBeans:1106, AbstractApplicationContext (org.springframework.context.support)
doClose:1075, AbstractApplicationContext (org.springframework.context.support)
close:1021, AbstractApplicationContext (org.springframework.context.support)
close:1365, SpringApplication (org.springframework.boot)
exit:1352, SpringApplication (org.springframework.boot)
main:14, Application (com.xxx.mybatch)

But when the Java process is finally exiting, the shutdown hook is called trying to tear down the reporter again in this call stack:

flush:265, AsyncReporter$BoundedAsyncReporter (zipkin2.reporter)
run:144, ZipkinAutoConfiguration$1 (org.springframework.cloud.sleuth.autoconfig.zipkin2)

And since the async reporter is already closed by Spring the flush method will throw this exception:

Exception in thread "Thread-3" zipkin2.reporter.ClosedSenderException
	at zipkin2.reporter.AsyncReporter$BoundedAsyncReporter.flush(AsyncReporter.java:265)
	at org.springframework.cloud.sleuth.autoconfig.zipkin2.ZipkinAutoConfiguration$1.run(ZipkinAutoConfiguration.java:144)

breiler avatar Sep 12 '22 07:09 breiler

Maybe something got fixed in Zipkin and we no longer need to register the shutdown hook - we'll need to look into this

marcingrzejszczak avatar Sep 12 '22 08:09 marcingrzejszczak