Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

2.0.1 client 关闭异常 #5842

Closed
Panpannn opened this issue May 25, 2021 · 12 comments · Fixed by #5949
Closed

2.0.1 client 关闭异常 #5842

Panpannn opened this issue May 25, 2021 · 12 comments · Fixed by #5949
Assignees
@shiyiyue1102
Labels
area/Client Related to Nacos Client SDK kind/enhancement Category issues or prs related to enhancement. version/2.x
Milestone
2.0.2

Comments

@Panpannn
Copy link

Panpannn commented May 25, 2021 •
edited

环境:
2.0.1 nacos-server
2.0.1 nacos-client

现象:
异常如下, grpc客户端在注销服务,取消订阅之前关闭了,导致注销失败,请问是bug吗,如果不是请问是哪里配置有问题吗?

[2021-05-25 15:45:42,343] WARN [com.alibaba.nacos.client.remote.worker] naming[93] [] Grpc connection disconnect
[2021-05-25 15:45:42,343] INFO [com.alibaba.nacos.client.remote.worker] ClientWorker[632] [] [config-] DisConnected,clear listen context...
[2021-05-25 15:45:42,447] INFO [SpringContextShutdownHook] ThreadPoolTaskScheduler[218] [] Shutting down ExecutorService 'Nacos-Watch-Task-Scheduler'
[2021-05-25 15:45:42,556] ERROR [SpringContextShutdownHook] client[99] [] Send request fail, request=SubscribeServiceRequest, retryTimes=0,errorMessage=Client not connected,current status:SHUTDOWN
[2021-05-25 15:45:42,666] ERROR [SpringContextShutdownHook] client[99] [] Send request fail, request=SubscribeServiceRequest, retryTimes=1,errorMessage=Client not connected,current status:SHUTDOWN
[2021-05-25 15:45:42,776] ERROR [SpringContextShutdownHook] client[99] [] Send request fail, request=SubscribeServiceRequest, retryTimes=2,errorMessage=Client not connected,current status:SHUTDOWN
[2021-05-25 15:45:42,785] ERROR [SpringContextShutdownHook] NacosWatch[170] [] namingService unsubscribe failed, properties:NacosDiscoveryProperties
[2021-05-25 15:45:42,790] INFO [SpringContextShutdownHook] NacosServiceRegistry[90] [] De-registering from Nacos Server now...
[2021-05-25 15:45:42,791] INFO [SpringContextShutdownHook] naming[108] [] [DEREGISTER-SERVICE] deregistering service gateway with instance: Instance
[2021-05-25 15:45:42,887] ERROR [com.alibaba.nacos.client.Worker] client[99] [] Send request fail, request=ConfigBatchListenRequest, retryTimes=0,errorMessage=Client not connected,current status:SHUTDOWN
[2021-05-25 15:45:42,903] ERROR [SpringContextShutdownHook] client[99] [] Send request fail, request=InstanceRequest, retryTimes=0,errorMessage=Client not connected,current status:SHUTDOWN
[2021-05-25 15:45:42,998] ERROR [com.alibaba.nacos.client.Worker] client[99] [] Send request fail, request=ConfigBatchListenRequest, retryTimes=1,errorMessage=Client not connected,current status:SHUTDOWN
[2021-05-25 15:45:43,013] ERROR [SpringContextShutdownHook] client[99] [] Send request fail, request=InstanceRequest, retryTimes=1,errorMessage=Client not connected,current status:SHUTDOWN
[2021-05-25 15:45:43,108] ERROR [com.alibaba.nacos.client.Worker] client[99] [] Send request fail, request=ConfigBatchListenRequest, retryTimes=2,errorMessage=Client not connected,current status:SHUTDOWN
@KomachiSion KomachiSion added area/Client Related to Nacos Client SDK area/Config version/2.x and removed area/Config labels May 25, 2021
@KomachiSion
Copy link
Collaborator

注销失败应该只是报错一下， 实际上连接断开的时候，nacos-server会自动注销。

从日志来看，似乎是先调用了关闭连接，然后才触发spring的shutdown hook。

@EarthChen
Copy link

这里同样的问题，虽然不影响功能，但是打印许多 error ，可能会影响服务告警

环境：
2.0.1 nacos-server
2.0.1 nacos-client

2021-05-31 18:14:46.572 ERROR 12561 --- [extShutdownHook] com.alibaba.nacos.common.remote.client   : Send request fail, request=SubscribeServiceRequest{headers={accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDc5fQ.74Tlf8hfjotIlylOi5P6zJbOXMuz289bJvEtLrKw0h8, app=unknown}, requestId='null'}, retryTimes=0,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:46.673 ERROR 12561 --- [extShutdownHook] com.alibaba.nacos.common.remote.client   : Send request fail, request=SubscribeServiceRequest{headers={accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDc5fQ.74Tlf8hfjotIlylOi5P6zJbOXMuz289bJvEtLrKw0h8, app=unknown}, requestId='null'}, retryTimes=1,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:46.778 ERROR 12561 --- [extShutdownHook] com.alibaba.nacos.common.remote.client   : Send request fail, request=SubscribeServiceRequest{headers={accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDc5fQ.74Tlf8hfjotIlylOi5P6zJbOXMuz289bJvEtLrKw0h8, app=unknown}, requestId='null'}, retryTimes=2,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:46.790 ERROR 12561 --- [extShutdownHook] c.a.cloud.nacos.discovery.NacosWatch     : namingService unsubscribe failed, properties:NacosDiscoveryProperties{serverAddr='188.131.182.232:30848', endpoint='', namespace='rz-ares', watchDelay=30000, logName='', service='ares-user-server', weight=1.0, clusterName='DEFAULT', group='DEFAULT_GROUP', namingLoadCacheAtStart='false', metadata={preserved.register.source=SPRING_CLOUD}, registerEnabled=true, ip='192.168.200.159', networkInterface='', port=9000, secure=false, accessKey='', secretKey='', heartBeatInterval=null, heartBeatTimeout=null, ipDeleteTimeout=null}

com.alibaba.nacos.api.exception.NacosException: Request nacos server failed: 
	at com.alibaba.nacos.client.naming.remote.gprc.NamingGrpcClientProxy.requestToServer(NamingGrpcClientProxy.java:213) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.remote.gprc.NamingGrpcClientProxy.unsubscribe(NamingGrpcClientProxy.java:182) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.remote.NamingClientProxyDelegate.unsubscribe(NamingClientProxyDelegate.java:156) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.NacosNamingService.unsubscribe(NacosNamingService.java:411) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.cloud.nacos.discovery.NacosWatch.stop(NacosWatch.java:142) [spring-cloud-starter-alibaba-nacos-discovery-2.2.2.RELEASE.jar:2.2.2.RELEASE]
	at com.alibaba.cloud.nacos.discovery.NacosWatch.stop(NacosWatch.java:81) [spring-cloud-starter-alibaba-nacos-discovery-2.2.2.RELEASE.jar:2.2.2.RELEASE]
	at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:238) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.context.support.DefaultLifecycleProcessor.access$300(DefaultLifecycleProcessor.java:53) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:377) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:210) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.context.support.DefaultLifecycleProcessor.onClose(DefaultLifecycleProcessor.java:128) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1022) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.doClose(ServletWebServerApplicationContext.java:170) [spring-boot-2.3.2.RELEASE.jar:2.3.2.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:949) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
Caused by: com.alibaba.nacos.api.exception.NacosException: Client not connected,current status:SHUTDOWN
	at com.alibaba.nacos.common.remote.client.RpcClient.request(RpcClient.java:628) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.common.remote.client.RpcClient.request(RpcClient.java:608) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.remote.gprc.NamingGrpcClientProxy.requestToServer(NamingGrpcClientProxy.java:203) ~[nacos-client-2.0.1.jar:na]
	... 13 common frames omitted

2021-05-31 18:14:46.794  INFO 12561 --- [extShutdownHook] c.a.c.n.registry.NacosServiceRegistry    : De-registering from Nacos Server now...
2021-05-31 18:14:46.795  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [DEREGISTER-SERVICE] rz-ares deregistering service ares-user-server with instance: Instance{instanceId='null', ip='192.168.200.159', port=9000, weight=1.0, healthy=true, enabled=true, ephemeral=true, clusterName='DEFAULT', serviceName='null', metadata={}}
2021-05-31 18:14:46.898 ERROR 12561 --- [extShutdownHook] com.alibaba.nacos.common.remote.client   : Send request fail, request=InstanceRequest{headers={accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDc5fQ.74Tlf8hfjotIlylOi5P6zJbOXMuz289bJvEtLrKw0h8, app=unknown}, requestId='null'}, retryTimes=0,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:47.003 ERROR 12561 --- [extShutdownHook] com.alibaba.nacos.common.remote.client   : Send request fail, request=InstanceRequest{headers={accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDc5fQ.74Tlf8hfjotIlylOi5P6zJbOXMuz289bJvEtLrKw0h8, app=unknown}, requestId='null'}, retryTimes=1,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:47.068 ERROR 12561 --- [s.client.Worker] com.alibaba.nacos.common.remote.client   : Send request fail, request=ConfigBatchListenRequest{headers={charset=UTF-8, exConfigInfo=true, Client-AppName=unknown, Client-RequestTS=1622456086966, Client-RequestToken=61e7d02080f3a22a044877b1cfcb89b9, accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDY2fQ.8OYOT-uZ3gmKVmpuCX_jSJRoJ89_R_rCYwVAl0eUcjo, Timestamp=1622456086966}, requestId='null'}, retryTimes=0,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:47.106 ERROR 12561 --- [extShutdownHook] com.alibaba.nacos.common.remote.client   : Send request fail, request=InstanceRequest{headers={accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDc5fQ.74Tlf8hfjotIlylOi5P6zJbOXMuz289bJvEtLrKw0h8, app=unknown}, requestId='null'}, retryTimes=2,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:47.106 ERROR 12561 --- [extShutdownHook] c.a.c.n.registry.NacosServiceRegistry    : ERR_NACOS_DEREGISTER, de-register failed...NacosRegistration{nacosDiscoveryProperties=NacosDiscoveryProperties{serverAddr='188.131.182.232:30848', endpoint='', namespace='rz-ares', watchDelay=30000, logName='', service='ares-user-server', weight=1.0, clusterName='DEFAULT', group='DEFAULT_GROUP', namingLoadCacheAtStart='false', metadata={preserved.register.source=SPRING_CLOUD}, registerEnabled=true, ip='192.168.200.159', networkInterface='', port=9000, secure=false, accessKey='', secretKey='', heartBeatInterval=null, heartBeatTimeout=null, ipDeleteTimeout=null}},

com.alibaba.nacos.api.exception.NacosException: Request nacos server failed: 
	at com.alibaba.nacos.client.naming.remote.gprc.NamingGrpcClientProxy.requestToServer(NamingGrpcClientProxy.java:213) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.remote.gprc.NamingGrpcClientProxy.deregisterService(NamingGrpcClientProxy.java:112) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.remote.NamingClientProxyDelegate.deregisterService(NamingClientProxyDelegate.java:100) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.NacosNamingService.deregisterInstance(NacosNamingService.java:174) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.NacosNamingService.deregisterInstance(NacosNamingService.java:164) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.cloud.nacos.registry.NacosServiceRegistry.deregister(NacosServiceRegistry.java:98) ~[spring-cloud-starter-alibaba-nacos-discovery-2.2.2.RELEASE.jar:2.2.2.RELEASE]
	at org.springframework.cloud.client.serviceregistry.AbstractAutoServiceRegistration.deregister(AbstractAutoServiceRegistration.java:256) [spring-cloud-commons-2.2.3.RELEASE.jar:2.2.3.RELEASE]
	at org.springframework.cloud.client.serviceregistry.AbstractAutoServiceRegistration.stop(AbstractAutoServiceRegistration.java:271) [spring-cloud-commons-2.2.3.RELEASE.jar:2.2.3.RELEASE]
	at org.springframework.cloud.client.serviceregistry.AbstractAutoServiceRegistration.destroy(AbstractAutoServiceRegistration.java:208) [spring-cloud-commons-2.2.3.RELEASE.jar:2.2.3.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_275]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_275]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_275]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_275]
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:389) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeDestroyMethods(InitDestroyAnnotationBeanPostProcessor.java:347) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeDestruction(InitDestroyAnnotationBeanPostProcessor.java:177) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:242) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:579) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:551) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1092) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:512) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1085) [spring-beans-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1061) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1030) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.doClose(ServletWebServerApplicationContext.java:170) [spring-boot-2.3.2.RELEASE.jar:2.3.2.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:949) [spring-context-5.2.8.RELEASE.jar:5.2.8.RELEASE]
Caused by: com.alibaba.nacos.api.exception.NacosException: Client not connected,current status:SHUTDOWN
	at com.alibaba.nacos.common.remote.client.RpcClient.request(RpcClient.java:628) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.common.remote.client.RpcClient.request(RpcClient.java:608) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.naming.remote.gprc.NamingGrpcClientProxy.requestToServer(NamingGrpcClientProxy.java:203) ~[nacos-client-2.0.1.jar:na]
	... 25 common frames omitted

2021-05-31 18:14:47.107  INFO 12561 --- [extShutdownHook] c.a.c.n.registry.NacosServiceRegistry    : De-registration finished.
2021-05-31 18:14:47.108  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.cache.ServiceInfoHolder do shutdown begin
2021-05-31 18:14:47.108  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.backups.FailoverReactor do shutdown begin
2021-05-31 18:14:47.171 ERROR 12561 --- [s.client.Worker] com.alibaba.nacos.common.remote.client   : Send request fail, request=ConfigBatchListenRequest{headers={charset=UTF-8, exConfigInfo=true, Client-AppName=unknown, Client-RequestTS=1622456086966, Client-RequestToken=61e7d02080f3a22a044877b1cfcb89b9, accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDY2fQ.8OYOT-uZ3gmKVmpuCX_jSJRoJ89_R_rCYwVAl0eUcjo, Timestamp=1622456086966}, requestId='null'}, retryTimes=1,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:47.275 ERROR 12561 --- [s.client.Worker] com.alibaba.nacos.common.remote.client   : Send request fail, request=ConfigBatchListenRequest{headers={charset=UTF-8, exConfigInfo=true, Client-AppName=unknown, Client-RequestTS=1622456086966, Client-RequestToken=61e7d02080f3a22a044877b1cfcb89b9, accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDY2fQ.8OYOT-uZ3gmKVmpuCX_jSJRoJ89_R_rCYwVAl0eUcjo, Timestamp=1622456086966}, requestId='null'}, retryTimes=2,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:47.276 ERROR 12561 --- [s.client.Worker] c.a.n.client.config.impl.ClientWorker    : Async listen config change error 

com.alibaba.nacos.api.exception.NacosException: Client not connected,current status:SHUTDOWN
	at com.alibaba.nacos.common.remote.client.RpcClient.request(RpcClient.java:628) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.config.impl.ClientWorker$ConfigRpcTransportClient.requestProxy(ClientWorker.java:976) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.config.impl.ClientWorker$ConfigRpcTransportClient.requestProxy(ClientWorker.java:951) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.config.impl.ClientWorker$ConfigRpcTransportClient.executeConfigListen(ClientWorker.java:757) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.config.impl.ClientWorker$ConfigRpcTransportClient$3.run(ClientWorker.java:677) [nacos-client-2.0.1.jar:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_275]
	at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266) [na:1.8.0_275]
	at java.util.concurrent.FutureTask.run(FutureTask.java) [na:1.8.0_275]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_275]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_275]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_275]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_275]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_275]

2021-05-31 18:14:47.414  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.backups.FailoverReactor do shutdown stop
2021-05-31 18:14:47.414  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.cache.ServiceInfoHolder do shutdown stop
2021-05-31 18:14:47.414  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.remote.NamingClientProxyDelegate do shutdown begin
2021-05-31 18:14:47.414  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.core.ServiceInfoUpdateService do shutdown begin
2021-05-31 18:14:47.723  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.core.ServiceInfoUpdateService do shutdown stop
2021-05-31 18:14:47.723  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.core.ServerListManager do shutdown begin
2021-05-31 18:14:47.724  WARN 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [NamingHttpClientManager] Start destroying NacosRestTemplate
2021-05-31 18:14:47.724  WARN 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [NamingHttpClientManager] Destruction of the end
2021-05-31 18:14:47.724  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.core.ServerListManager do shutdown stop
2021-05-31 18:14:47.724  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.remote.http.NamingHttpClientProxy do shutdown begin
2021-05-31 18:14:47.724  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.beat.BeatReactor do shutdown begin
2021-05-31 18:14:47.725  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.beat.BeatReactor do shutdown stop
2021-05-31 18:14:47.725  WARN 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [NamingHttpClientManager] Start destroying NacosRestTemplate
2021-05-31 18:14:47.725  WARN 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [NamingHttpClientManager] Destruction of the end
2021-05-31 18:14:47.725  INFO 12561 --- [extShutdownHook] c.a.n.client.identify.CredentialWatcher  : [null] CredentialWatcher is stopped
2021-05-31 18:14:47.726  INFO 12561 --- [extShutdownHook] c.a.n.client.identify.CredentialService  : [null] CredentialService is freed
2021-05-31 18:14:47.726  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.remote.http.NamingHttpClientProxy do shutdown stop
2021-05-31 18:14:47.727  INFO 12561 --- [t.remote.worker] com.alibaba.nacos.common.remote.client   : [fb9b5139-cea2-4047-b0a0-cd41ae211f27]Notify disconnected event to listeners
2021-05-31 18:14:47.727  WARN 12561 --- [t.remote.worker] com.alibaba.nacos.client.naming          : Grpc connection disconnect
2021-05-31 18:14:47.727  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.remote.NamingClientProxyDelegate do shutdown stop
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.cache.ServiceInfoHolder do shutdown begin
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.backups.FailoverReactor do shutdown begin
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.backups.FailoverReactor do shutdown stop
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.cache.ServiceInfoHolder do shutdown stop
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.remote.NamingClientProxyDelegate do shutdown begin
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.core.ServiceInfoUpdateService do shutdown begin
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.core.ServiceInfoUpdateService do shutdown stop
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.core.ServerListManager do shutdown begin
2021-05-31 18:14:47.728  WARN 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [NamingHttpClientManager] Start destroying NacosRestTemplate
2021-05-31 18:14:47.728  WARN 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [NamingHttpClientManager] Destruction of the end
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.core.ServerListManager do shutdown stop
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.remote.http.NamingHttpClientProxy do shutdown begin
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.beat.BeatReactor do shutdown begin
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.beat.BeatReactor do shutdown stop
2021-05-31 18:14:47.728  WARN 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [NamingHttpClientManager] Start destroying NacosRestTemplate
2021-05-31 18:14:47.728  WARN 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : [NamingHttpClientManager] Destruction of the end
2021-05-31 18:14:47.728  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.remote.http.NamingHttpClientProxy do shutdown stop
2021-05-31 18:14:47.729  INFO 12561 --- [extShutdownHook] com.alibaba.nacos.client.naming          : com.alibaba.nacos.client.naming.remote.NamingClientProxyDelegate do shutdown stop
2021-05-31 18:14:47.729  INFO 12561 --- [t.remote.worker] com.alibaba.nacos.common.remote.client   : [fb9b5139-cea2-4047-b0a0-cd41ae211f27]Notify disconnected event to listeners
2021-05-31 18:14:47.729  WARN 12561 --- [t.remote.worker] com.alibaba.nacos.client.naming          : Grpc connection disconnect
2021-05-31 18:14:47.730  INFO 12561 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2021-05-31 18:14:47.771  INFO 12561 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2021-05-31 18:14:52.436 ERROR 12561 --- [s.client.Worker] com.alibaba.nacos.common.remote.client   : Send request fail, request=ConfigBatchListenRequest{headers={charset=UTF-8, exConfigInfo=true, Client-AppName=unknown, Client-RequestTS=1622456092333, Client-RequestToken=c0b94539f68d69c39b41971018cceff5, accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDY2fQ.8OYOT-uZ3gmKVmpuCX_jSJRoJ89_R_rCYwVAl0eUcjo, Timestamp=1622456092334}, requestId='null'}, retryTimes=0,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:52.536 ERROR 12561 --- [s.client.Worker] com.alibaba.nacos.common.remote.client   : Send request fail, request=ConfigBatchListenRequest{headers={charset=UTF-8, exConfigInfo=true, Client-AppName=unknown, Client-RequestTS=1622456092333, Client-RequestToken=c0b94539f68d69c39b41971018cceff5, accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDY2fQ.8OYOT-uZ3gmKVmpuCX_jSJRoJ89_R_rCYwVAl0eUcjo, Timestamp=1622456092334}, requestId='null'}, retryTimes=1,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:52.640 ERROR 12561 --- [s.client.Worker] com.alibaba.nacos.common.remote.client   : Send request fail, request=ConfigBatchListenRequest{headers={charset=UTF-8, exConfigInfo=true, Client-AppName=unknown, Client-RequestTS=1622456092333, Client-RequestToken=c0b94539f68d69c39b41971018cceff5, accessToken=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJyei1hcmVzLXJ3IiwiZXhwIjoxNjIyNDc0MDY2fQ.8OYOT-uZ3gmKVmpuCX_jSJRoJ89_R_rCYwVAl0eUcjo, Timestamp=1622456092334}, requestId='null'}, retryTimes=2,errorMessage=Client not connected,current status:SHUTDOWN
2021-05-31 18:14:52.641 ERROR 12561 --- [s.client.Worker] c.a.n.client.config.impl.ClientWorker    : Async listen config change error 

com.alibaba.nacos.api.exception.NacosException: Client not connected,current status:SHUTDOWN
	at com.alibaba.nacos.common.remote.client.RpcClient.request(RpcClient.java:628) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.config.impl.ClientWorker$ConfigRpcTransportClient.requestProxy(ClientWorker.java:976) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.config.impl.ClientWorker$ConfigRpcTransportClient.requestProxy(ClientWorker.java:951) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.config.impl.ClientWorker$ConfigRpcTransportClient.executeConfigListen(ClientWorker.java:757) ~[nacos-client-2.0.1.jar:na]
	at com.alibaba.nacos.client.config.impl.ClientWorker$ConfigRpcTransportClient$3.run(ClientWorker.java:677) [nacos-client-2.0.1.jar:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_275]
	at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266) [na:1.8.0_275]
	at java.util.concurrent.FutureTask.run(FutureTask.java) [na:1.8.0_275]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_275]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_275]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_275]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_275]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_275]

2021-05-31 18:14:53.405  INFO 12561 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

@yumin5723
Copy link

@EarthChen 麻烦问一下，这个问题有解决吗

@EarthChen
Copy link

@EarthChen 麻烦问一下，这个问题有解决吗

没有 不过影响不大，服务是可以正常下线的

@yumin5723
Copy link

@EarthChen 麻烦问一下，这个问题有解决吗

没有 不过影响不大，服务是可以正常下线的

嗯，我这边跟你是一样的问题，也是告警很烦

@EarthChen
Copy link

@EarthChen 麻烦问一下，这个问题有解决吗

没有 不过影响不大，服务是可以正常下线的

嗯，我这边跟你是一样的问题，也是告警很烦

我这边只是测试了一下 等修好再更新 client 把 目前还使用的是老版

@yumin5723
Copy link

@EarthChen 麻烦问一下，这个问题有解决吗

没有 不过影响不大，服务是可以正常下线的

嗯，我这边跟你是一样的问题，也是告警很烦

我这边只是测试了一下 等修好再更新 client 把 目前还使用的是老版

意思是老版本的客户端没这个问题？

@EarthChen
Copy link

@EarthChen 麻烦问一下，这个问题有解决吗

没有 不过影响不大，服务是可以正常下线的

嗯，我这边跟你是一样的问题，也是告警很烦

我这边只是测试了一下 等修好再更新 client 把 目前还使用的是老版

意思是老版本的客户端没这个问题？

老版本走的不睡是grpc 的 http 长轮询

@yumin5723
Copy link

@EarthChen 麻烦问一下，这个问题有解决吗

没有 不过影响不大，服务是可以正常下线的

嗯，我这边跟你是一样的问题，也是告警很烦

我这边只是测试了一下 等修好再更新 client 把 目前还使用的是老版

意思是老版本的客户端没这个问题？

老版本走的不睡是grpc 的 http 长轮询

您现在是哪个版本？

@yumin5723
Copy link

注销失败应该只是报错一下， 实际上连接断开的时候，nacos-server会自动注销。

从日志来看，似乎是先调用了关闭连接，然后才触发spring的shutdown hook。

1.x版本，我用的1.4.1没有这个问题

@litgh
Copy link

litgh commented Jun 1, 2021

看了2.0.1的源码. RpcClient:390行, 在启动的时候注册了一个shutdownhook执行RpcClient.this.shutdown(), 进程关闭的时先触发的这个逻辑关闭了client, 其它bean在执行生命周期的关闭方法时去注销服务. 这时rpcClient已经关闭了.

@shiyiyue1102
Copy link
Collaborator

client

We will fix it in the next release.

@shiyiyue1102 shiyiyue1102 linked a pull request Jun 4, 2021 that will close this issue
fix query sla multi connection model ;add rpc client error log; optimize client shutdown #5949
Merged
5 tasks
@KomachiSion KomachiSion added the kind/enhancement Category issues or prs related to enhancement. label Jun 4, 2021
@KomachiSion KomachiSion added this to the 2.0.2 milestone Jun 4, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@shiyiyue1102 shiyiyue1102

Labels
area/Client Related to Nacos Client SDK kind/enhancement Category issues or prs related to enhancement. version/2.x
Projects
None yet
Milestone
2.0.2
6 participants
@yumin5723 @litgh @EarthChen @shiyiyue1102 @KomachiSion @Panpannn