search

alibaba / spring-cloud-alibaba

Spring Cloud Alibaba provides a one-stop solution for application development for the distributed solutions of Alibaba middleware.
https://sca.aliyun.com
Apache License 2.0
27.91k stars 8.33k forks source link

cloud-alibaba: stop dubbo app, shutdown hook exception #1588

Open pengyusong opened 4 years ago

pengyusong commented 4 years ago

spring boot 2.1.x spring cloud alibaba 2.1.x dubbo springboot start 2.7.6 dubbo 2.7.6

Ctrl+C停止应用的时候，出现如下错误日志(PS: dubbo 2.7.4版本不存在此问题）：

2020-07-15 23:23:56.595  INFO 5108 --- [bboShutdownHook] o.a.d.rpc.protocol.dubbo.DubboProtocol   :  [DUBBO] Unexport service: dubbo://172.18.243.32:20880/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&bind.ip=172.18.243.32&bind.port=20880&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=5108&qos.enable=false&release=2.7.6&revision=1.0-SNAPSHOT&side=provider&timestamp=1594826630962&version=1.0, dubbo version: 2.7.6, current host: 172.18.243.32
2020-07-15 23:23:56.595  INFO 5108 --- [bboShutdownHook] o.a.d.rpc.protocol.dubbo.DubboProtocol   :  [DUBBO] Unexport service: dubbo://172.18.243.32:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService?anyhost=true&application=usercenter&bind.ip=172.18.243.32&bind.port=20880&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&group=usercenter&interface=com.alibaba.cloud.dubbo.service.DubboMetadataService&logger=slf4j&methods=getAllServiceKeys,getServiceRestMetadata,getExportedURLs,getAllExportedURLs&pid=5108&qos.enable=false&release=2.7.6&revision=2.1.2.RELEASE&side=provider&timestamp=1594826631464&version=1.0.0, dubbo version: 2.7.6, current host: 172.18.243.32
2020-07-15 23:23:56.599  INFO 5108 --- [bboShutdownHook] org.apache.dubbo.qos.server.Server       :  [DUBBO] qos-server stopped., dubbo version: 2.7.6, current host: 172.18.243.32
2020-07-15 23:23:56.599  INFO 5108 --- [bboShutdownHook] o.a.d.rpc.protocol.injvm.InjvmProtocol   :  [DUBBO] Unexport service: injvm://127.0.0.1/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&bind.ip=172.18.243.32&bind.port=20880&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=5108&qos.enable=false&release=2.7.6&revision=1.0-SNAPSHOT&side=provider&timestamp=1594826630962&version=1.0, dubbo version: 2.7.6, current host: 172.18.243.32
2020-07-15 23:23:56.601  INFO 5108 --- [bboShutdownHook] c.a.c.d.registry.SpringCloudRegistry     :  [DUBBO] Unregister: dubbo://172.18.243.32:20880/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=5108&release=2.7.6&revision=1.0-SNAPSHOT&side=provider&timestamp=1594826630962&version=1.0, dubbo version: 2.7.6, current host: 172.18.243.32
2020-07-15 23:23:56.601  INFO 5108 --- [bboShutdownHook] c.a.c.d.registry.SpringCloudRegistry     :  [DUBBO] Unsubscribe: provider://172.18.243.32:20880/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&bind.ip=172.18.243.32&bind.port=20880&category=configurators&check=false&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=5108&qos.enable=false&release=2.7.6&revision=1.0-SNAPSHOT&side=provider&timestamp=1594826630962&version=1.0, dubbo version: 2.7.6, current host: 172.18.243.32
2020-07-15 23:23:56.602  INFO 5108 --- [bboShutdownHook] c.a.c.d.registry.SpringCloudRegistry     :  [DUBBO] Unregister: dubbo://172.18.243.32:20880/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=5108&release=2.7.6&revision=1.0-SNAPSHOT&side=provider&timestamp=1594826630962&version=1.0, dubbo version: 2.7.6, current host: 172.18.243.32
2020-07-15 23:23:56.607  WARN 5108 --- [bboShutdownHook] o.a.d.r.integration.RegistryProtocol     :  [DUBBO] unsubscribe listener == null, dubbo version: 2.7.6, current host: 172.18.243.32
java.lang.IllegalArgumentException: unsubscribe listener == null
        at org.apache.dubbo.registry.support.AbstractRegistry.unsubscribe(AbstractRegistry.java:325) ~[dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.registry.support.FailbackRegistry.unsubscribe(FailbackRegistry.java:329) ~[dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.registry.ListenerRegistryWrapper.unsubscribe(ListenerRegistryWrapper.java:129) ~[dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.registry.integration.RegistryProtocol$ExporterChangeableWrapper.unexport(RegistryProtocol.java:735) ~[dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.registry.integration.RegistryProtocol$DestroyableExporter.unexport(RegistryProtocol.java:554) [dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.config.ServiceConfig.unexport(ServiceConfig.java:170) [dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.config.bootstrap.DubboBootstrap.lambda$unexportServices$16(DubboBootstrap.java:926) [dubbo-2.7.6.jar!/:2.7.6]
        at java.util.ArrayList.forEach(ArrayList.java:1257) ~[na:1.8.0_251]
        at org.apache.dubbo.config.bootstrap.DubboBootstrap.unexportServices(DubboBootstrap.java:924) [dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.config.bootstrap.DubboBootstrap.destroy(DubboBootstrap.java:1046) [dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.config.bootstrap.DubboBootstrap$1.callback(DubboBootstrap.java:191) ~[dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.common.function.ThrowableAction.execute(ThrowableAction.java:46) ~[dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.common.lang.ShutdownHookCallbacks.lambda$callback$0(ShutdownHookCallbacks.java:70) ~[dubbo-2.7.6.jar!/:2.7.6]
        at java.lang.Iterable.forEach(Iterable.java:75) ~[na:1.8.0_251]
        at org.apache.dubbo.common.lang.ShutdownHookCallbacks.callback(ShutdownHookCallbacks.java:70) ~[dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.config.DubboShutdownHook.callback(DubboShutdownHook.java:85) ~[dubbo-2.7.6.jar!/:2.7.6]
        at org.apache.dubbo.config.DubboShutdownHook.run(DubboShutdownHook.java:73) ~[dubbo-2.7.6.jar!/:2.7.6]
pengyusong commented 4 years ago

猜测： 从上述日志和替换dubbo2.7.4正常日志来看，2.7.6版本停止的时unregister和unsubscribe UserRpcService 两次，第二次因为第一次已经移除了listener，所以获取不到，为NULL

pengyusong commented 4 years ago

增加： dubbo 2.7.6版本除了Ctrl+C停止时出现上述日志以外，在idea中开发，由于代码变动，springboot devtools自动重启也会报错:

java.lang.IllegalStateException: ApplicationConfig.application == null

切换成2.7.4，springboot devtools使得应用重启而不报错。

所以，2.7.6 在停止dubbo应用的时候，有问题？

PS：2.7.6 停止的时候线程名时bboShutdownHook，而2.7.4停止的时候就是普通的Thread-65，所以，应该是2.7.6停止应用改由JVM的shutdownhook机制实现而引入的BUG？

pengyusong commented 4 years ago

附上2.7.4版本的dubbo停止的日志：

2020-07-16 01:43:44.450  INFO 4844 --- [      Thread-65] .b.c.e.AwaitingNonWebApplicationListener :  [Dubbo] Current Spring Boot Application is about to shutdown...
2020-07-16 01:43:44.453  INFO 4844 --- [      Thread-65] c.a.c.d.registry.SpringCloudRegistry     :  [DUBBO] Unregister: dubbo://192.168.43.123:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService?anyhost=true&application=usercenter&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&group=usercenter&interface=com.alibaba.cloud.dubbo.service.DubboMetadataService&logger=slf4j&methods=getAllServiceKeys,getServiceRestMetadata,getExportedURLs,getAllExportedURLs&pid=4844&release=2.7.4&revision=2.1.2.RELEASE&side=provider&timestamp=1594835008214&version=1.0.0, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.454  INFO 4844 --- [      Thread-65] c.a.c.d.registry.SpringCloudRegistry     :  [DUBBO] Unsubscribe: provider://192.168.43.123:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService?anyhost=true&application=usercenter&bind.ip=192.168.43.123&bind.port=20880&category=configurators&check=false&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&group=usercenter&interface=com.alibaba.cloud.dubbo.service.DubboMetadataService&logger=slf4j&methods=getAllServiceKeys,getServiceRestMetadata,getExportedURLs,getAllExportedURLs&pid=4844&qos.enable=false&release=2.7.4&revision=2.1.2.RELEASE&side=provider&timestamp=1594835008214&version=1.0.0, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.455  INFO 4844 --- [      Thread-65] c.a.c.d.s.DubboMetadataServiceExporter   : The Dubbo service[<dubbo:service path="com.alibaba.cloud.dubbo.service.DubboMetadataService" ref="com.alibaba.cloud.dubbo.service.IntrospectiveDubboMetadataService@26ed78a1" prefix="dubbo.service.com.alibaba.cloud.dubbo.service.DubboMetadataService" generic="false" exported="true" unexported="true" interface="com.alibaba.cloud.dubbo.service.DubboMetadataService" version="1.0.0" dynamic="true" group="usercenter" deprecated="false" id="com.alibaba.cloud.dubbo.service.DubboMetadataService" valid="true" />] has been unexported.
2020-07-16 01:43:44.456  INFO 4844 --- [export-thread-1] o.a.d.r.integration.RegistryProtocol     :  [DUBBO] Waiting 10000ms for registry to notify all consumers before unexport. Usually, this is called when you use dubbo API, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.456  INFO 4844 --- [      Thread-65] o.a.d.r.support.AbstractRegistryFactory  :  [DUBBO] Close all registries [], dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.456  INFO 4844 --- [      Thread-65] o.a.d.rpc.protocol.dubbo.DubboProtocol   :  [DUBBO] Close dubbo server: /192.168.43.123:20880, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.458  INFO 4844 --- [      Thread-65] o.a.d.remoting.transport.AbstractServer  :  [DUBBO] Close NettyServer bind /0.0.0.0:20880, export /192.168.43.123:20880, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.462  INFO 4844 --- [      Thread-65] o.a.d.rpc.protocol.dubbo.DubboProtocol   :  [DUBBO] Unexport service: dubbo://192.168.43.123:20880/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&bean.name=ServiceBean:com.nhk.rpc.dubbo.service.UserRpcService:1.0&bind.ip=192.168.43.123&bind.port=20880&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=4844&qos.enable=false&release=2.7.4&revision=1.0&side=provider&timestamp=1594835005916&version=1.0, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.462  INFO 4844 --- [      Thread-65] o.a.d.rpc.protocol.dubbo.DubboProtocol   :  [DUBBO] Unexport service: dubbo://192.168.43.123:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService?anyhost=true&application=usercenter&bind.ip=192.168.43.123&bind.port=20880&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&group=usercenter&interface=com.alibaba.cloud.dubbo.service.DubboMetadataService&logger=slf4j&methods=getAllServiceKeys,getServiceRestMetadata,getExportedURLs,getAllExportedURLs&pid=4844&qos.enable=false&release=2.7.4&revision=2.1.2.RELEASE&side=provider&timestamp=1594835008214&version=1.0.0, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.465  INFO 4844 --- [      Thread-65] org.apache.dubbo.qos.server.Server       :  [DUBBO] qos-server stopped., dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.466  INFO 4844 --- [      Thread-65] o.a.d.rpc.protocol.injvm.InjvmProtocol   :  [DUBBO] Unexport service: injvm://127.0.0.1/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&bean.name=ServiceBean:com.nhk.rpc.dubbo.service.UserRpcService:1.0&bind.ip=192.168.43.123&bind.port=20880&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=4844&qos.enable=false&release=2.7.4&revision=1.0&side=provider&timestamp=1594835005916&version=1.0, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.466  INFO 4844 --- [      Thread-65] c.a.c.d.registry.SpringCloudRegistry     :  [DUBBO] Unregister: dubbo://192.168.43.123:20880/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&bean.name=ServiceBean:com.nhk.rpc.dubbo.service.UserRpcService:1.0&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=4844&release=2.7.4&revision=1.0&side=provider&timestamp=1594835005916&version=1.0, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.467  INFO 4844 --- [      Thread-65] c.a.c.d.registry.SpringCloudRegistry     :  [DUBBO] Unsubscribe: provider://192.168.43.123:20880/com.nhk.rpc.dubbo.service.UserRpcService?anyhost=true&application=usercenter&bean.name=ServiceBean:com.nhk.rpc.dubbo.service.UserRpcService:1.0&bind.ip=192.168.43.123&bind.port=20880&category=configurators&check=false&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&interface=com.nhk.rpc.dubbo.service.UserRpcService&logger=slf4j&methods=getId2UserMapByUserIdList&pid=4844&qos.enable=false&release=2.7.4&revision=1.0&side=provider&timestamp=1594835005916&version=1.0, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.468  INFO 4844 --- [export-thread-1] o.a.d.r.integration.RegistryProtocol     :  [DUBBO] Waiting 10000ms for registry to notify all consumers before unexport. Usually, this is called when you use dubbo API, dubbo version: 2.7.4, current host: 192.168.43.123
2020-07-16 01:43:44.486  INFO 4844 --- [      Thread-65] o.s.s.c.ThreadPoolTaskScheduler          : Shutting down ExecutorService 'scheduledExecutorService'
2020-07-16 01:43:44.495  INFO 4844 --- [      Thread-65] c.a.c.n.registry.NacosServiceRegistry    : De-registering from Nacos Server now...
2020-07-16 01:43:44.592  INFO 4844 --- [      Thread-65] c.a.c.n.registry.NacosServiceRegistry    : De-registration finished.
2020-07-16 01:43:44.605  INFO 4844 --- [      Thread-65] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2020-07-16 01:43:44.654  INFO 4844 --- [      Thread-65] o.s.s.c.ThreadPoolTaskScheduler          : Shutting down ExecutorService 'scheduledExecutorService'
2020-07-16 01:43:44.895  INFO 4844 --- [      Thread-65] c.a.c.d.s.DubboGenericServiceFactory     : The Dubbo GenericService ReferenceBeans are destroying...
2020-07-16 01:43:44.897  INFO 4844 --- [      Thread-65] f.a.ReferenceAnnotationBeanPostProcessor : class org.apache.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor was destroying!
2020-07-16 01:43:44.899  INFO 4844 --- [      Thread-65] com.zaxxer.hikari.HikariDataSource       : nhk-user - Shutdown initiated...
2020-07-16 01:43:44.933  INFO 4844 --- [      Thread-65] com.zaxxer.hikari.HikariDataSource       : nhk-user - Shutdown completed.