search

apache / dubbo-spring-boot-project

Spring Boot Project for Apache Dubbo
https://dubbo.apache.org
Apache License 2.0
5.41k stars 1.88k forks source link

Dubbo生产者在DubboBootstrap启动就绪前注册到Nacos中，导致重启后消费者无法获取生产者暴露的服务 #768

Closed mattmok closed 3 years ago

mattmok commented 3 years ago

项目依赖： spring-cloud-starter-dubbo:2.2.3.RELEASE spring-cloud-starter-alibaba-nacos-discovery:2.2.3.RELEASE dubbo:2.7.8

生产者日志：

[INFO ] 2020-12-27T19:57:42,857 [restartedMain] ServiceClassPostProcessor -  [DUBBO] 2 annotated Dubbo's @Service Components { [Bean definition with name 'demoServiceImpl': ... } were scanned under package[com.tiamaes.cloud.exmaple.service], dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:51,143 [restartedMain] DubboServiceMetadataRepository - The metadata of Dubbo services has been initialized
[INFO ] 2020-12-27T19:57:51,283 [restartedMain] TomcatWebServer - Tomcat started on port(s): 8080 (http) with context path ''
[INFO ] 2020-12-27T19:57:52,622 [restartedMain] DubboBootstrap -  [DUBBO] No value is configured in the registry, the DynamicConfigurationFactory extension[name : spring-cloud] does not support as the config center, dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:52,673 [restartedMain] DubboBootstrap -  [DUBBO] The registry[<dubbo:registry address="localhost" protocol="spring-cloud" port="0" />] will be not used as the metadata center, dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:52,839 [restartedMain] DubboBootstrap -  [DUBBO] DubboBootstrap has been initialized!, dubbo version: 2.7.8, current host: 172.31.1.92
[WARN ] 2020-12-27T19:57:52,878 [restartedMain] ServiceConfig -  [DUBBO] Use random available port(20880) for protocol dubbo, dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:52,912 [restartedMain] ServiceConfig -  [DUBBO] Export dubbo service com.alibaba.cloud.dubbo.service.DubboMetadataService to local registry url : injvm://127.0.0.1/com.alibaba.cloud.dubbo.service.DubboMetadataService?anyhost=true&application=example-http&bind.ip=172.31.1.92&bind.port=20880..., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:52,912 [restartedMain] ServiceConfig -  [DUBBO] Register dubbo service com.alibaba.cloud.dubbo.service.DubboMetadataService url dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService... to registry 
[INFO ] 2020-12-27T19:57:53,420 [restartedMain] DubboCloudRegistry -  [DUBBO] Register: dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService..., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:54,684 [restartedMain] DubboCloudRegistry -  [DUBBO] Subscribe: provider://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService..., dubbo version: 2.7.8, current host: 172.31.1.92
[DEBUG] 2020-12-27T19:57:54,706 [restartedMain] DubboCloudRegistry - The subscribed URL[provider://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService...] will notify all URLs : [dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService...]
[DEBUG] 2020-12-27T19:57:54,707 [restartedMain] RegistryProtocol -  [DUBBO] original override urls: [dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService...], dubbo version: 2.7.8, current host: 172.31.1.92
[DEBUG] 2020-12-27T19:57:54,708 [restartedMain] RegistryProtocol -  [DUBBO] subscribe url: provider://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService..., override urls: [], dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:54,742 [restartedMain] DynamicConfigurationServiceNameMapping -  [DUBBO] Dubbo service[example-http] mapped to interface name[com.alibaba.cloud.dubbo.service.DubboMetadataService]., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:54,743 [restartedMain] DubboMetadataServiceExporter - The Dubbo service[<dubbo:service exported="true" unexported="false" />] has been exported.
[INFO ] 2020-12-27T19:57:54,779 [restartedMain] DubboBootstrap -  [DUBBO] DubboBootstrap is starting..., dubbo version: 2.7.8, current host: 172.31.1.92
INFO ] 2020-12-27T19:57:54,787 [restartedMain] ServiceConfig -  [DUBBO] No valid ip found from environment, try to find valid host from DNS., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:54,790 [restartedMain] ServiceConfig -  [DUBBO] Export dubbo service com.tiamaes.cloud.example.service.JsonService to local registry url : injvm://127.0.0.1/com.tiamaes.cloud.example.service.JsonService..., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:54,791 [restartedMain] ServiceConfig -  [DUBBO] Register dubbo service com.tiamaes.cloud.example.service.JsonService url dubbo://172.31.1.92:20880/com.tiamaes.cloud.example.service.JsonService..., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:54,792 [restartedMain] DubboCloudRegistry -  [DUBBO] Register: dubbo://172.31.1.92:20880/com.tiamaes.cloud.example.service.JsonService..., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:56,062 [restartedMain] DubboCloudRegistry -  [DUBBO] Subscribe: provider://172.31.1.92:20880/com.tiamaes.cloud.example.service.JsonService..., dubbo version: 2.7.8, current host: 172.31.1.92
...
[INFO ] 2020-12-27T19:57:57,427 [restartedMain] DynamicConfigurationServiceNameMapping -  [DUBBO] Dubbo service[null] mapped to interface name[com.tiamaes.cloud.example.service.DemoService]., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:57,437 [restartedMain] DubboBootstrap -  [DUBBO] DubboBootstrap is ready., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:57,437 [restartedMain] DubboBootstrap -  [DUBBO] DubboBootstrap has started., dubbo version: 2.7.8, current host: 172.31.1.

消费者日志：

[INFO ] 2020-12-27T19:57:33,045 [NettyClientWorker-1-1] NettyClientHandler -  [DUBBO] The connection of /172.31.1.92:54052 -> /172.31.1.92:20880 is disconnected., dubbo version: 2.7.8, current host: 172.31.1.92
[DEBUG] 2020-12-27T19:57:33,045 [DubboClientHandler-172.31.1.92:20880-thread-2] DubboProtocol -  [DUBBO] disconnected from /172.31.1.92:20880,url:dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService..., dubbo version: 2.7.8, current host: 172.31.1.92
[INFO ] 2020-12-27T19:57:55,777 [com.alibaba.nacos.naming.client.listener] DubboServiceDiscoveryAutoConfiguration - The event of the service instances[name : example-http , size : 1] change is about to be dispatched
[DEBUG] 2020-12-27T19:57:55,781 [com.alibaba.nacos.naming.client.listener] DubboCloudRegistry - The subscribed URL[consumer://172.31.1.92/org.apache.dubbo.rpc.service.GenericService...] will notify all URLs : [dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService...]
[DEBUG] 2020-12-27T19:57:55,784 [com.alibaba.nacos.naming.client.listener] RegistryDirectory -  [DUBBO] destroy invoker[dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService...] success. , dubbo version: 2.7.8, current host: 172.31.1.92
[ERROR] 2020-12-27T19:57:55,791 [com.alibaba.nacos.naming.client.listener] DubboMetadataServiceInvocationHandler - Failed to invoke the method getExportedURLs in the service org.apache.dubbo.rpc.service.GenericService. Tried 3 times of the providers [172.31.1.92:20880] (1/1) from the registry localhost:9090 on the consumer 172.31.1.92 using the dubbo version 2.7.8. Last error is: Failed to invoke remote method: $invoke, provider: dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService..., cause: message can not send, because channel is closed . url:dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService...
org.apache.dubbo.rpc.RpcException: Failed to invoke the method getExportedURLs in the service org.apache.dubbo.rpc.service.GenericService. Tried 3 times of the providers [172.31.1.92:20880] (1/1) from the registry localhost:9090 on the consumer 172.31.1.92 using the dubbo version 2.7.8. Last error is: Failed to invoke remote method: $invoke, provider: dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService... cause: message can not send, because channel is closed . url:dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService...
    at org.apache.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:113)
    at org.apache.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:260)
    at org.apache.dubbo.rpc.cluster.interceptor.ClusterInterceptor.intercept(ClusterInterceptor.java:47)
    at org.apache.dubbo.rpc.cluster.support.wrapper.AbstractCluster$InterceptorInvokerNode.invoke(AbstractCluster.java:92)
    at org.apache.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:88)
    at org.apache.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:74)
    at org.apache.dubbo.common.bytecode.proxy0.$invoke(proxy0.java)
    at com.alibaba.cloud.dubbo.service.DubboMetadataServiceInvocationHandler.invoke(DubboMetadataServiceInvocationHandler.java:48)
    at com.sun.proxy.$Proxy142.getExportedURLs(Unknown Source)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.getExportedURLs(DubboCloudRegistry.java:424)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.getTemplateExportedURLs(DubboCloudRegistry.java:324)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.lambda$cloneExportedURLs$6(DubboCloudRegistry.java:288)
    at java.util.ArrayList.forEach(ArrayList.java:1257)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.cloneExportedURLs(DubboCloudRegistry.java:284)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.getExportedURLs(DubboCloudRegistry.java:265)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.subscribeURLs(DubboCloudRegistry.java:240)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.subscribeURLs(DubboCloudRegistry.java:227)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.lambda$subscribeURLs$2(DubboCloudRegistry.java:206)
    at java.lang.Iterable.forEach(Iterable.java:75)
    at java.util.Collections$UnmodifiableCollection.forEach(Collections.java:1080)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.subscribeURLs(DubboCloudRegistry.java:204)
    at com.alibaba.cloud.dubbo.registry.DubboCloudRegistry.lambda$subscribeURLs$0(DubboCloudRegistry.java:194)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:404)
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:361)
    at com.alibaba.cloud.dubbo.autoconfigure.DubboServiceDiscoveryAutoConfiguration.dispatchServiceInstancesChangedEvent(DubboServiceDiscoveryAutoConfiguration.java:175)
    at com.alibaba.cloud.dubbo.autoconfigure.DubboServiceDiscoveryAutoConfiguration.access$200(DubboServiceDiscoveryAutoConfiguration.java:108)
    at com.alibaba.cloud.dubbo.autoconfigure.DubboServiceDiscoveryAutoConfiguration$NacosConfiguration.lambda$subscribeEventListener$1(DubboServiceDiscoveryAutoConfiguration.java:557)
    at com.alibaba.nacos.client.naming.core.EventDispatcher$Notifier.run(EventDispatcher.java:177)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.dubbo.remoting.RemotingException: message can not send, because channel is closed . url:dubbo://172.31.1.92:20880/com.alibaba.cloud.dubbo.service.DubboMetadataService?anyhost=true&application=example-rpc&bind.ip=172.31.1.92&bind.port=20880&check=false&codec=dubbo&deprecated=false&dubbo=2.0.2&dynamic=true&generic=true&group=example-http&heartbeat=60000&interface=com.alibaba.cloud.dubbo.service.DubboMetadataService&methods=getAllServiceKeys,getServiceRestMetadata,getExportedURLs,getAllExportedURLs...&version=1.0.0

这样会导致服务端重启后，客户端无法重新获取暴露的接口，最终将RegistryDirectory类中的forbidden被设置为true，访问接口时会报以下错误：

[ERROR] 2020-12-27T20:43:25,488 [http-nio-9091-exec-1] GlobalControllerAdvice - No provider available from registry localhost:9090 for service com.tiamaes.cloud.example.service.JsonService on consumer 172.31.1.92 use dubbo version 2.7.8, please check status of providers(disabled, not registered or in blacklist).
org.apache.dubbo.rpc.RpcException: No provider available from registry localhost:9090 for service com.tiamaes.cloud.example.service.JsonService on consumer 172.31.1.92 use dubbo version 2.7.8, please check status of providers(disabled, not registered or in blacklist).
    at org.apache.dubbo.registry.integration.RegistryDirectory.doList(RegistryDirectory.java:599)
    at org.apache.dubbo.rpc.cluster.directory.AbstractDirectory.list(AbstractDirectory.java:74)
    at org.apache.dubbo.rpc.cluster.support.AbstractClusterInvoker.list(AbstractClusterInvoker.java:292)
    at org.apache.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:257)
    at org.apache.dubbo.rpc.cluster.interceptor.ClusterInterceptor.intercept(ClusterInterceptor.java:47)
    at org.apache.dubbo.rpc.cluster.support.wrapper.AbstractCluster$InterceptorInvokerNode.invoke(AbstractCluster.java:92)
    at org.apache.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:88)
    at org.apache.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:74)
    at org.apache.dubbo.common.bytecode.proxy2.testJson(proxy2.java)
    at com.tiamaes.cloud.exmaple.DemoController.dubbo2(DemoController.java:55)
    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)
...

有时候会可以自动关闭重建连接，有时候不会

[INFO ] 2020-12-27T21:13:11,965 [com.alibaba.nacos.naming.client.listener] NettyClient -  [DUBBO] Close old netty channel [id: 0x687f61b0, L:/172.31.1.92:55963 ! R:/172.31.1.92:20880] on create new netty channel [id: 0xfa9880c8, L:/172.31.1.92:56003 - R:/172.31.1.92:20880], dubbo version: 2.7.8, current host: 172.31.1.92
mattmok commented 3 years ago

好像是IDEA的问题，重启时没有触发关闭hook。我重新测试一下。

zybbjtu commented 2 years ago

最终是什么问题呢？