De-registering：nacos注册的springcloud微服务偶发执行shutdownHook，服务自动down掉

wggy commented 3 years ago

Describe the bug A clear and concise description of what the bug is.

程序异常退出，启动一台服务，偶发shutdown springcloud服务挂掉，启动三台服务，同样偶发springcloud服务挂掉，且是同时挂掉！！！

下面是日志shutdownHook日志：

Expected behavior 2020-12-08 10:51:13.901 INFO 9163 --- [extShutdownHook] o.s.s.c.ThreadPoolTaskScheduler : Shutting down ExecutorService 'Nacos-Watch-Task-Scheduler' 2020-12-08 10:51:13.913 INFO 9163 --- [extShutdownHook] c.a.c.n.registry.NacosServiceRegistry : De-registering from Nacos Server now... 2020-12-08 10:51:13.916 INFO 9163 --- [extShutdownHook] c.a.c.n.registry.NacosServiceRegistry : De-registration finished. 2020-12-08 10:51:24.266 WARN 9163 --- [extShutdownHook] o.s.b.f.support.DisposableBeanAdapter : Destroy method 'close' on bean with name 'nacosServiceRegistry' threw an exception: java.lang.NullPointerException 2020-12-08 10:51:24.281 INFO 9163 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor : Shutting down ExecutorService 'applicationTaskExecutor' 2020-12-08 10:51:24.462 INFO 9163 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'browserPersistenceUnit' 2020-12-08 10:51:24.469 INFO 9163 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource : Browser-HikariPool - Shutdown initiated... 2020-12-08 10:51:24.473 INFO 9163 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource : Browser-HikariPool - Shutdown completed. 2020-12-08 10:51:24.473 INFO 9163 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'sopPersistenceUnit' 2020-12-08 10:51:24.474 INFO 9163 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource : SOP-HikariPool - Shutdown initiated... 2020-12-08 10:51:24.486 INFO 9163 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource : SOP-HikariPool - Shutdown completed.

Acutally behavior

How to Reproduce Steps to reproduce the behavior:

Go to '...'
Click on '....'
Scroll down to '....'
See error

Desktop (please complete the following information):

OS: [e.g. Centos]
Version [e.g. nacos-server 1.3.1, nacos-client 1.3.1]
Module [e.g. naming/config]
SDK [e.g. original, spring-cloud-alibaba-nacos, dubbo]

Additional context Add any other context about the problem here.

wggy commented 3 years ago

补一张shutdown后的日志图片：

chuntaojun commented 3 years ago

是不是自己程序的bug引起的，建议将日志信息打印的更为详细一点看下

KomachiSion commented 3 years ago

触发shutdownhook肯定是收到了程序停止的信号，或者哪里主动调用了nacos的shutdown方法，你需要自己排查下。

而且从日志看，不仅是nacos shutdown了，连接池也shutdown了（nacos没有连接池引用）。所以肯定是你程序自己的问题，触发了shutdownhook。

wggy commented 3 years ago

2020-12-10 07:59:55.887 DEBUG 8525 --- [nio-8091-exec-4] org.hibernate.loader.Loader : Result set row: 0 2020-12-10 07:59:55.887 DEBUG 8525 --- [nio-8091-exec-4] org.hibernate.loader.Loader : Result row: EntityKey[com.gitee.sop.openapi.browser.entity.UsersEntity#15869307353321] 2020-12-10 07:59:55.888 DEBUG 8525 --- [nio-8091-exec-4] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit 2020-12-10 07:59:55.888 DEBUG 8525 --- [nio-8091-exec-4] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(473046285)] 2020-12-10 07:59:55.888 DEBUG 8525 --- [nio-8091-exec-4] o.h.e.t.internal.TransactionImpl : committing 2020-12-10 07:59:55.891 DEBUG 8525 --- [nio-8091-exec-4] o.s.jdbc.datasource.DataSourceUtils : Resetting read-only flag of JDBC Connection [HikariProxyConnection@416495301 wrapping com.mysql.cj.jdbc.ConnectionImpl@30370bb1] 2020-12-10 07:59:55.892 DEBUG 8525 --- [nio-8091-exec-4] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction 2020-12-10 07:59:55.893 DEBUG 8525 --- [nio-8091-exec-4] m.m.a.RequestResponseBodyMethodProcessor : Using 'application/json', given [application/json, text/plain, /] and supported [application/json, application/+json, application/json, application/+json, application/cbor] 2020-12-10 07:59:55.893 INFO 8525 --- [nio-8091-exec-4] c.g.sop.servercommon.util.AesApiUtil : key: 1ZqI7pWriFbQVma8, iv: qI7pWriFbQVma8RO 2020-12-10 07:59:55.893 INFO 8525 --- [nio-8091-exec-4] c.g.s.o.config.EncryptResponseAdvice : OriginResponseJson: [{"installed":false,"userId":15869307353321,"username":"中文En11"}] 2020-12-10 07:59:55.893 INFO 8525 --- [nio-8091-exec-4] c.g.s.o.config.EncryptResponseAdvice : oauthToken:41ZqI7pWriFbQVma8ROo, EncodedData: +igTKQI8H2YAHwuyzmcz3X7IC67JMaYaPVDm/JUBw/05P5OV4NTa4b0wh5nEOGcpo+LCtCj2yAz2up3fXUaC6h7cwq2e773WATaXiNPcDkM= 2020-12-10 07:59:55.893 DEBUG 8525 --- [nio-8091-exec-4] m.m.a.RequestResponseBodyMethodProcessor : Writing [{data=+igTKQI8H2YAHwuyzmcz3X7IC67JMaYaPVDm/JUBw/05P5OV4NTa4b0wh5nEOGcpo+LCtCj2yAz2up3fXUaC6h7cwq2e77 (truncated)...] 2020-12-10 07:59:55.895 DEBUG 8525 --- [nio-8091-exec-4] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor 2020-12-10 07:59:55.895 DEBUG 8525 --- [nio-8091-exec-4] o.s.web.servlet.DispatcherServlet : Completed 200 OK 2020-12-10 07:59:55.895 DEBUG 8525 --- [nio-8091-exec-4] o.a.coyote.http11.Http11InputBuffer : Before fill(): [true], parsingRequestLine: [true], parsingRequestLinePhase: [0], parsingRequestLineStart: [0], byteBuffer.position() [0] 2020-12-10 07:59:55.895 DEBUG 8525 --- [nio-8091-exec-4] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3d4fcee:org.apache.tomcat.util.net.NioChannel@5ea996c9:java.nio.channels.SocketChannel[connected local=/172.32.33.81:8091 remote=/172.32.33.81:34006]], Read from buffer: [0] 2020-12-10 07:59:55.896 DEBUG 8525 --- [nio-8091-exec-4] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3d4fcee:org.apache.tomcat.util.net.NioChannel@5ea996c9:java.nio.channels.SocketChannel[connected local=/172.32.33.81:8091 remote=/172.32.33.81:34006]], Read direct from socket: [0] 2020-12-10 07:59:55.896 DEBUG 8525 --- [nio-8091-exec-4] o.a.coyote.http11.Http11InputBuffer : Received [] 2020-12-10 07:59:55.896 DEBUG 8525 --- [nio-8091-exec-4] o.apache.coyote.http11.Http11Processor : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3d4fcee:org.apache.tomcat.util.net.NioChannel@5ea996c9:java.nio.channels.SocketChannel[connected local=/172.32.33.81:8091 remote=/172.32.33.81:34006]], Status in: [OPEN_READ], State out: [OPEN] 2020-12-10 07:59:55.896 DEBUG 8525 --- [nio-8091-exec-4] org.apache.tomcat.util.net.NioEndpoint : Registered read interest for [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@3d4fcee:org.apache.tomcat.util.net.NioChannel@5ea996c9:java.nio.channels.SocketChannel[connected local=/172.32.33.81:8091 remote=/172.32.33.81:34006]] 2020-12-10 07:59:57.232 DEBUG 8525 --- [ing.beat.sender] s.n.www.protocol.http.HttpURLConnection : sun.net.www.MessageHeader@6e496b3a11 pairs: {PUT /nacos/v1/ns/instance/beat?app=unknown&serviceName=DEFAULT_GROUP%40%40sop-openapi&namespaceId=public&port=8091&clusterName=DEFAULT&ip=172.32.33.81 HTTP/1.1: null}{Content-Type: application/x-www-form-urlencoded;charset=UTF-8}{Accept-Charset: UTF-8}{Accept-Encoding: gzip,deflate,sdch}{Client-Version: 1.3.3}{User-Agent: Nacos-Java-Client:v1.3.3}{RequestId: 65af9b60-4e2d-45e4-98e1-07c3308269c0}{Request-Module: Naming}{Host: 52.81.162.154:8084}{Accept: text/html, image/gif, image/jpeg, ; q=.2, /; q=.2}{Connection: keep-alive} 2020-12-10 07:59:57.233 DEBUG 8525 --- [ing.beat.sender] s.n.www.protocol.http.HttpURLConnection : sun.net.www.MessageHeader@2af12a276 pairs: {null: HTTP/1.1 200}{Content-Type: application/json;charset=UTF-8}{Transfer-Encoding: chunked}{Date: Thu, 10 Dec 2020 07:59:57 GMT}{Keep-Alive: timeout=60}{Connection: keep-alive} 2020-12-10 07:59:58.860 DEBUG 8525 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool : Browser-HikariPool - Before cleanup stats (total=1, active=0, idle=1, waiting=0) 2020-12-10 07:59:58.860 DEBUG 8525 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool : Browser-HikariPool - After cleanup stats (total=1, active=0, idle=1, waiting=0) 2020-12-10 07:59:58.860 DEBUG 8525 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool : Browser-HikariPool - Fill pool skipped, pool is at sufficient level. 2020-12-10 08:00:02.234 DEBUG 8525 --- [ing.beat.sender] s.n.www.protocol.http.HttpURLConnection : sun.net.www.MessageHeader@22c9003411 pairs: {PUT /nacos/v1/ns/instance/beat?app=unknown&serviceName=DEFAULT_GROUP%40%40sop-openapi&namespaceId=public&port=8091&clusterName=DEFAULT&ip=172.32.33.81 HTTP/1.1: null}{Content-Type: application/x-www-form-urlencoded;charset=UTF-8}{Accept-Charset: UTF-8}{Accept-Encoding: gzip,deflate,sdch}{Client-Version: 1.3.3}{User-Agent: Nacos-Java-Client:v1.3.3}{RequestId: 1bf81de5-f9af-44a6-9783-77bace82bdf5}{Request-Module: Naming}{Host: 52.81.162.154:8084}{Accept: text/html, image/gif, image/jpeg, ; q=.2, /; q=.2}{Connection: keep-alive} 2020-12-10 08:00:02.236 DEBUG 8525 --- [ing.beat.sender] s.n.www.protocol.http.HttpURLConnection : sun.net.www.MessageHeader@2121a8916 pairs: {null: HTTP/1.1 200}{Content-Type: application/json;charset=UTF-8}{Transfer-Encoding: chunked}{Date: Thu, 10 Dec 2020 08:00:02 GMT}{Keep-Alive: timeout=60}{Connection: keep-alive} 2020-12-10 08:00:02.728 DEBUG 8525 --- [.naming.updater] s.n.www.protocol.http.HttpURLConnection : sun.net.www.MessageHeader@452dd99611 pairs: {GET /nacos/v1/ns/instance/list?app=unknown&healthyOnly=false&namespaceId=public&clientIP=172.32.33.81&serviceName=DEFAULT_GROUP%40%40sop-openapi&udpPort=43394&clusters=DEFAULT HTTP/1.1: null}{Content-Type: application/x-www-form-urlencoded;charset=UTF-8}{Accept-Charset: UTF-8}{Accept-Encoding: gzip,deflate,sdch}{Client-Version: 1.3.3}{User-Agent: Nacos-Java-Client:v1.3.3}{RequestId: 6010f8b5-f3fd-4558-99fd-e1f30e34951e}{Request-Module: Naming}{Host: 52.81.162.154:8084}{Accept: text/html, image/gif, image/jpeg, ; q=.2, /; q=.2}{Connection: keep-alive} 2020-12-10 08:00:02.730 DEBUG 8525 --- [.naming.updater] s.n.www.protocol.http.HttpURLConnection : sun.net.www.MessageHeader@555dc8706 pairs: {null: HTTP/1.1 200}{Content-Type: application/json;charset=UTF-8}{Transfer-Encoding: chunked}{Date: Thu, 10 Dec 2020 08:00:02 GMT}{Keep-Alive: timeout=60}{Connection: keep-alive} 2020-12-10 08:00:07.237 DEBUG 8525 --- [ing.beat.sender] s.n.www.protocol.http.HttpURLConnection : sun.net.www.MessageHeader@414173411 pairs: {PUT /nacos/v1/ns/instance/beat?app=unknown&serviceName=DEFAULT_GROUP%40%40sop-openapi&namespaceId=public&port=8091&clusterName=DEFAULT&ip=172.32.33.81 HTTP/1.1: null}{Content-Type: application/x-www-form-urlencoded;charset=UTF-8}{Accept-Charset: UTF-8}{Accept-Encoding: gzip,deflate,sdch}{Client-Version: 1.3.3}{User-Agent: Nacos-Java-Client:v1.3.3}{RequestId: a118e5de-608c-43c2-aff0-a912af7c07e8}{Request-Module: Naming}{Host: 52.81.162.154:8084}{Accept: text/html, image/gif, image/jpeg, ; q=.2, /; q=.2}{Connection: keep-alive} 2020-12-10 08:00:07.238 DEBUG 8525 --- [ing.beat.sender] s.n.www.protocol.http.HttpURLConnection : sun.net.www.MessageHeader@2797b5836 pairs: {null: HTTP/1.1 200}{Content-Type: application/json;charset=UTF-8}{Transfer-Encoding: chunked}{Date: Thu, 10 Dec 2020 08:00:07 GMT}{Keep-Alive: timeout=60}{Connection: keep-alive} 2020-12-10 08:00:07.312 DEBUG 8525 --- [extShutdownHook] ConfigServletWebServerApplicationContext : Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@3e57cd70, started on Thu Dec 10 07:26:14 UTC 2020, parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@61a485d2 2020-12-10 08:00:07.331 DEBUG 8525 --- [extShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 2147483647 2020-12-10 08:00:07.333 DEBUG 8525 --- [extShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Bean 'documentationPluginsBootstrapper' completed its stop procedure 2020-12-10 08:00:07.335 DEBUG 8525 --- [extShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Bean 'webServerGracefulShutdown' completed its stop procedure 2020-12-10 08:00:07.335 DEBUG 8525 --- [extShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 2147483646 2020-12-10 08:00:07.391 DEBUG 8525 --- [extShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Bean 'webServerStartStop' completed its stop procedure 2020-12-10 08:00:07.391 DEBUG 8525 --- [extShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 0 2020-12-10 08:00:07.393 INFO 8525 --- [extShutdownHook] o.s.s.c.ThreadPoolTaskScheduler : Shutting down ExecutorService 'Nacos-Watch-Task-Scheduler' 2020-12-10 08:00:07.396 DEBUG 8525 --- [extShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Bean 'nacosWatch' completed its stop procedure 2020-12-10 08:00:07.398 DEBUG 8525 --- [extShutdownHook] o.s.d.r.l.RedisMessageListenerContainer : Stopped RedisMessageListenerContainer 2020-12-10 08:00:07.411 INFO 8525 --- [extShutdownHook] c.a.c.n.registry.NacosServiceRegistry : De-registering from Nacos Server now... 2020-12-10 08:00:07.431 INFO 8525 --- [extShutdownHook] c.a.c.n.registry.NacosServiceRegistry : De-registration finished. 2020-12-10 08:00:16.380 DEBUG 8525 --- [ngPollService-1] c.c.f.a.i.RemoteConfigLongPollService : Long polling response: 304, url: http://172.32.33.81:8080/notifications/v2?cluster=default&appId=sop-openapi&ip=172.32.33.81&notifications=%5B%7B%22namespaceName%22%3A%22application%22%2C%22notificationId%22%3A50%7D%2C%7B%22namespaceName%22%3A%22sorts%22%2C%22notificationId%22%3A35%7D%2C%7B%22namespaceName%22%3A%22redis%22%2C%22notificationId%22%3A44%7D%5D 2020-12-10 08:00:16.381 DEBUG 8525 --- [ngPollService-1] c.c.f.a.i.RemoteConfigLongPollService : Long polling from http://172.32.33.81:8080/notifications/v2?cluster=default&appId=sop-openapi&ip=172.32.33.81&notifications=%5B%7B%22namespaceName%22%3A%22application%22%2C%22notificationId%22%3A50%7D%2C%7B%22namespaceName%22%3A%22sorts%22%2C%22notificationId%22%3A35%7D%2C%7B%22namespaceName%22%3A%22redis%22%2C%22notificationId%22%3A44%7D%5D 2020-12-10 08:00:17.737 WARN 8525 --- [extShutdownHook] o.s.b.f.support.DisposableBeanAdapter : Destroy method 'close' on bean with name 'nacosServiceRegistry' threw an exception

java.lang.NullPointerException: null at com.alibaba.cloud.nacos.NacosServiceManager.nacosServiceShutDown(NacosServiceManager.java:115) ~[spring-cloud-starter-alibaba-nacos-discovery-2.2.3.RELEASE.jar!/:2.2.3.RELEASE] at com.alibaba.cloud.nacos.registry.NacosServiceRegistry.close(NacosServiceRegistry.java:112) ~[spring-cloud-starter-alibaba-nacos-discovery-2.2.3.RELEASE.jar!/:2.2.3.RELEASE] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_161] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_161] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_161] at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_161] at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:339) [spring-beans-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:273) [spring-beans-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:587) [spring-beans-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:559) [spring-beans-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1092) [spring-beans-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:520) [spring-beans-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1085) [spring-beans-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1061) [spring-context-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1030) [spring-context-5.2.9.RELEASE.jar!/:5.2.9.RELEASE] at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.doClose(ServletWebServerApplicationContext.java:170) [spring-boot-2.3.4.RELEASE.jar!/:2.3.4.RELEASE] at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:949) [spring-context-5.2.9.RELEASE.jar!/:5.2.9.RELEASE]

2020-12-10 08:00:17.816 INFO 8525 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor : Shutting down ExecutorService 'applicationTaskExecutor' 2020-12-10 08:00:17.821 DEBUG 8525 --- [extShutdownHook] io.lettuce.core.RedisChannelHandler : closeAsync() 2020-12-10 08:00:17.821 DEBUG 8525 --- [extShutdownHook] i.lettuce.core.protocol.DefaultEndpoint : [channel=0xd114962e, /172.32.33.81:35246 -> superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379, epid=0x1] closeAsync() 2020-12-10 08:00:17.827 DEBUG 8525 --- [ioEventLoop-4-1] io.lettuce.core.protocol.CommandHandler : [channel=0xd114962e, /172.32.33.81:35246 -> superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379, chid=0x1] channelInactive() 2020-12-10 08:00:17.828 DEBUG 8525 --- [extShutdownHook] io.lettuce.core.RedisClient : Initiate shutdown (100, 100, MILLISECONDS) 2020-12-10 08:00:17.829 DEBUG 8525 --- [ioEventLoop-4-1] i.lettuce.core.protocol.DefaultEndpoint : [channel=0xd114962e, /172.32.33.81:35246 -> superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379, epid=0x1] deactivating endpoint handler 2020-12-10 08:00:17.829 DEBUG 8525 --- [ioEventLoop-4-1] io.lettuce.core.protocol.CommandHandler : [channel=0xd114962e, /172.32.33.81:35246 -> superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379, chid=0x1] channelInactive() done 2020-12-10 08:00:17.830 DEBUG 8525 --- [ioEventLoop-4-1] i.l.core.protocol.ConnectionWatchdog : [channel=0xd114962e, /172.32.33.81:35246 -> superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379, last known addr=superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379] channelInactive() 2020-12-10 08:00:17.830 DEBUG 8525 --- [ioEventLoop-4-1] i.l.core.protocol.ConnectionWatchdog : [channel=0xd114962e, /172.32.33.81:35246 -> superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379, last known addr=superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379] Reconnect scheduling disabled 2020-12-10 08:00:17.831 DEBUG 8525 --- [ioEventLoop-4-1] io.lettuce.core.protocol.CommandHandler : [channel=0xd114962e, /172.32.33.81:35246 -> superbrowser-test.tvlcc1.ng.0001.cnn1.cache.amazonaws.com.cn/172.32.15.90:6379, chid=0x1] channelUnregistered() 2020-12-10 08:00:17.844 DEBUG 8525 --- [extShutdownHook] i.l.c.r.DefaultEventLoopGroupProvider : Release executor io.netty.channel.nio.NioEventLoopGroup@7774e262 2020-12-10 08:00:17.946 DEBUG 8525 --- [ioEventLoop-4-1] io.netty.buffer.PoolThreadCache : Freed 8 thread-local buffer(s) from thread: lettuce-nioEventLoop-4-1 2020-12-10 08:00:17.951 DEBUG 8525 --- [extShutdownHook] i.l.c.resource.DefaultClientResources : Initiate shutdown (0, 2, SECONDS) 2020-12-10 08:00:17.954 DEBUG 8525 --- [extShutdownHook] i.l.c.r.DefaultEventLoopGroupProvider : Initiate shutdown (0, 2, SECONDS) 2020-12-10 08:00:17.960 INFO 8525 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'browserPersistenceUnit' 2020-12-10 08:00:17.960 DEBUG 8525 --- [extShutdownHook] o.hibernate.internal.SessionFactoryImpl : HHH000031: Closing 2020-12-10 08:00:17.960 DEBUG 8525 --- [extShutdownHook] o.h.type.spi.TypeConfiguration$Scope : Un-scoping TypeConfiguration [org.hibernate.type.spi.TypeConfiguration$Scope@1bca4ab3] from SessionFactory [org.hibernate.internal.SessionFactoryImpl@1e008f36] 2020-12-10 08:00:17.960 DEBUG 8525 --- [extShutdownHook] o.h.s.i.AbstractServiceRegistryImpl : Implicitly destroying ServiceRegistry on de-registration of all child ServiceRegistries 2020-12-10 08:00:17.962 DEBUG 8525 --- [extShutdownHook] o.h.b.r.i.BootstrapServiceRegistryImpl : Implicitly destroying Boot-strap registry on de-registration of all child ServiceRegistries 2020-12-10 08:00:17.962 INFO 8525 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource : Browser-HikariPool - Shutdown initiated... 2020-12-10 08:00:17.962 DEBUG 8525 --- [extShutdownHook] com.zaxxer.hikari.pool.HikariPool : Browser-HikariPool - Before shutdown stats (total=1, active=0, idle=1, waiting=0) 2020-12-10 08:00:17.964 DEBUG 8525 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : Browser-HikariPool - Closing connection com.mysql.cj.jdbc.ConnectionImpl@30370bb1: (connection evicted) 2020-12-10 08:00:17.964 DEBUG 8525 --- [extShutdownHook] com.zaxxer.hikari.pool.HikariPool : Browser-HikariPool - After shutdown stats (total=0, active=0, idle=0, waiting=0) 2020-12-10 08:00:17.965 INFO 8525 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource : Browser-HikariPool - Shutdown completed. 2020-12-10 08:00:17.965 INFO 8525 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'sopPersistenceUnit' 2020-12-10 08:00:17.965 DEBUG 8525 --- [extShutdownHook] o.hibernate.internal.SessionFactoryImpl : HHH000031: Closing 2020-12-10 08:00:17.965 DEBUG 8525 --- [extShutdownHook] o.h.type.spi.TypeConfiguration$Scope : Un-scoping TypeConfiguration [org.hibernate.type.spi.TypeConfiguration$Scope@1361a50e] from SessionFactory [org.hibernate.internal.SessionFactoryImpl@36ac8a63] 2020-12-10 08:00:17.965 DEBUG 8525 --- [extShutdownHook] o.h.s.i.AbstractServiceRegistryImpl : Implicitly destroying ServiceRegistry on de-registration of all child ServiceRegistries 2020-12-10 08:00:17.966 DEBUG 8525 --- [extShutdownHook] o.h.b.r.i.BootstrapServiceRegistryImpl : Implicitly destroying Boot-strap registry on de-registration of all child ServiceRegistries 2020-12-10 08:00:17.966 INFO 8525 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource : SOP-HikariPool - Shutdown initiated... 2020-12-10 08:00:17.966 DEBUG 8525 --- [extShutdownHook] com.zaxxer.hikari.pool.HikariPool : SOP-HikariPool - Before shutdown stats (total=1, active=0, idle=1, waiting=0) 2020-12-10 08:00:17.966 DEBUG 8525 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : SOP-HikariPool - Closing connection com.mysql.cj.jdbc.ConnectionImpl@3f34c2af: (connection evicted) 2020-12-10 08:00:17.967 DEBUG 8525 --- [extShutdownHook] com.zaxxer.hikari.pool.HikariPool : SOP-HikariPool - After shutdown stats (total=0, active=0, idle=0, waiting=0) 2020-12-10 08:00:17.971 INFO 8525 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource : SOP-HikariPool - Shutdown completed.

wggy commented 3 years ago

确实是触发了shutdownHook，服务部署在aws云主机，nacos使用的是外网地址，不知道是否是心跳断开引起的shutdownHook

KomachiSion commented 3 years ago

nacos 本身不会触发，如果你发现是NacosServiceRegistry触发的，请提issue到SCA社区，不过我建议你排查一下自己的逻辑，大概率是你自己的逻辑触发了shutdown或者是aws帮你kill了。