spring cloud 服务重启 Exception caught (might be ok if at shutdown) 异常日志

 spring cloud 服务重启中遇到异常 info级别日志, 如下:

[INFO ] - [c.n.u.c.ShutdownEnabledTimer:59] - Exception caught (might be ok if at shutdown) [TraceInfo:-] 
java.lang.IllegalStateException: Shutdown in progress
	at java.lang.ApplicationShutdownHooks.remove(ApplicationShutdownHooks.java:82)
	at java.lang.Runtime.removeShutdownHook(Runtime.java:239)
	at com.netflix.util.concurrent.ShutdownEnabledTimer.cancel(ShutdownEnabledTimer.java:57)
	at com.netflix.loadbalancer.BaseLoadBalancer.cancelPingTask(BaseLoadBalancer.java:632)
	at com.netflix.loadbalancer.BaseLoadBalancer.shutdown(BaseLoadBalancer.java:883)
	at com.netflix.loadbalancer.DynamicServerListLoadBalancer.shutdown(DynamicServerListLoadBalancer.java:285)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:337)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:271)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1052)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1059)
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1035)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1011)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:961)
	at org.springframework.cloud.context.named.NamedContextFactory.destroy(NamedContextFactory.java:92)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:256)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1052)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1059)
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1035)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1011)
	at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:931)

根据日志追踪, 最终定位问题发生是在DynamicServerListLoadBalancer调用 shutdown 方法, 导致最终调用 ShutdownEnabledTimer 的cancel方法,

 

    public void cancel() {
        super.cancel();

        LOGGER.info("Shutdown hook removed for: {}", this.name);

        try {
            Runtime.getRuntime().removeShutdownHook(this.cancelThread);
        } catch (IllegalStateException ise) {
            LOGGER.info("Exception caught (might be ok if at shutdown)", ise);
        }

     }

执行完父类cancel方法后,执行removeShutdownHook这一步抛出异常, 最终会调用到 ApplicationShutdownHooks的remove方法 

    static synchronized boolean remove(Thread hook) {
        if(hooks == null)
            throw new IllegalStateException("Shutdown in progress");

        if (hook == null)
            throw new NullPointerException();

        return hooks.remove(hook) != null;
    }

在第一步验证hooks时 抛出异常.

猜测原因: 服务重启过程中, ApplicationShutdownHooks 已执行runHooks方法, 执行完成之后,  hooks置为null;

    static void runHooks() {
        Collection<Thread> threads;
        synchronized(ApplicationShutdownHooks.class) {
            threads = hooks.keySet();
            hooks = null;
        }

        for (Thread hook : threads) {
            hook.start();
        }
        for (Thread hook : threads) {
            try {
                hook.join();
            } catch (InterruptedException x) { }
        }
    }

添加hook的代码如下:

 

    public ShutdownEnabledTimer(String name, boolean daemon) {
        super(name, daemon);

        this.name = name;

        this.cancelThread = new Thread(new Runnable() {
            public void run() {
                ShutdownEnabledTimer.super.cancel();
            }
        });

        LOGGER.info("Shutdown hook installed for: {}", this.name);

        Runtime.getRuntime().addShutdownHook(this.cancelThread);
    }

执行调用了 ShutdownEnabledTimer 的cancelThread线程

 

验证: 工程新建 com.netflix.util.concurrent, 复制原有的ShutdownEnabledTimer 类, cancelThread 构造时添加日志

public ShutdownEnabledTimer(String name, boolean daemon) {
        super(name, daemon);

        this.name = name;

        this.cancelThread = new Thread(new Runnable() {
            public void run() {
                //添加日志
                log.info(Thread.currentThread().getName() + " is executed");
                ShutdownEnabledTimer.super.cancel();
            }
        });

        LOGGER.info("Shutdown hook installed for: {}", this.name);

        Runtime.getRuntime().addShutdownHook(this.cancelThread);
    }

部署服务, 重新启动.

观察日志, 发现在DynamicServerListLoadBalancer调用 shutdown 方法前, shutdownHook已执行.

 

综上, netflix中并未针对服务停止时划分专用的shutdown方法, 没有兼容timer hook线程先于其执行的情况, 但是其在日志中做了说明, 且针对该种异常进行了捕获, 虽有堆栈日志打出,但是并未影响服务的终止,可作为优化点, 但其实并不影响服务质量.

 

另外, 社区关于该问题的讨论(https://github.com/spring-cloud/spring-cloud-commons/issues/111),目前已经终止, 并未有修复的计划.

该问题已修复， https://github.com/spring-cloud/spring-cloud-netflix/commit/0c3fbc34f6b906bbe5ffc0a6ac5900357b67c72a 

 

针对spring cloud 版本 升级至 Finchley.SR3及后续版本即可屏蔽上述异常， 服务可以正常去注册中心注销服务。