出现错误的原因是消费端war没有启动成功, 但是zkClient和Dubbo的对应Thread启动了, web container无法加载对应的类,
INFO: Initializing ProtocolHandler ["http-bio-8081"]
Jun , :: PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8010"]
Jun , :: PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in ms
Jun , :: PM org.apache.catalina.core.StandardService startInternal
INFO: Starting service Catalina
Jun , :: PM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.
Jun , :: PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive /home/tomcat/tomcat7_jdk7_2/webapps/daemon.war
Jun , :: PM org.apache.catalina.startup.TldConfig execute
INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Jun , :: PM org.apache.catalina.core.StandardContext startInternal
SEVERE: One or more listeners failed to start. Full details will be found in the appropriate container log file
Jun , :: PM org.apache.catalina.core.StandardContext startInternal
SEVERE: Context [/daemon] startup failed due to previous errors
Jun , :: PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
SEVERE: The web application [/daemon] appears to have started a thread named [DubboRegistryFailedRetryTimer-thread-] but has failed to stop it. This is very likely to create a memory leak.
Jun , :: PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
然后在接下来的日志中
INFO: Starting ProtocolHandler ["http-bio-8081"]
Jun , :: PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8010"]
Jun , :: PM org.apache.catalina.startup.Catalina start
INFO: Server startup in ms
Jun , :: PM org.apache.catalina.loader.WebappClassLoaderBase loadClass
INFO: Illegal access: this web application instance has been stopped already. Could not load org.apache.zookeeper.proto.WatcherEvent. The eventual following stack trace is caused by an error thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access, and has no functional impact.
java.lang.IllegalStateException
at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:)
而Dubbo消费端未启动的原因, 是Spring初始化失败
::29.725 INFO org.springframework.web.context.ContextLoader# Root WebApplicationContext: initialization started
::29.867 INFO ework.web.context.support.XmlWebApplicationContext# Refreshing Root WebApplicationContext: startup date [Wed Jun :: CST ]; root of context hierarchy
::29.917 INFO ramework.beans.factory.xml.XmlBeanDefinitionReader# Loading XML bean definitions from class path resource [spring/spring-daemon.xml]
::30.232 INFO ramework.beans.factory.xml.XmlBeanDefinitionReader# Loading XML bean definitions from class path resource [spring/spring-daemon-dubbo.xml]
::30.316 INFO com.alibaba.dubbo.common.logger.LoggerFactory# using logger: com.alibaba.dubbo.common.logger.log4j.Log4jLoggerAdapter
::30.561 INFO beans.factory.config.PropertyPlaceholderConfigurer# Loading properties file from class path resource [application.properties]
::30.634 INFO work.scheduling.concurrent.ThreadPoolTaskScheduler# Initializing ExecutorService 'myScheduler'
::30.634 INFO essorRegistrationDelegate$BeanPostProcessorChecker# Bean 'myScheduler' of type [class org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
::30.661 INFO gframework.cache.ehcache.EhCacheManagerFactoryBean# Initializing EhCache CacheManager
::30.664 DEBUG net.sf.ehcache.config.ConfigurationFactory# Configuring ehcache from InputStream
::30.677 DEBUG net.sf.ehcache.config.DiskStoreConfiguration# Disk Store Path: /home/tomcat/tomcat7_jdk7_2/temp
::30.702 DEBUG net.sf.ehcache.util.PropertyUtil# propertiesString is null.
::30.713 DEBUG net.sf.ehcache.config.ConfigurationHelper# No CacheManagerEventListenerFactory class specified. Skipping...
::30.729 DEBUG net.sf.ehcache.Cache# No BootstrapCacheLoaderFactory class specified. Skipping...
::30.729 DEBUG net.sf.ehcache.Cache# CacheWriter factory not configured. Skipping...
::30.731 DEBUG net.sf.ehcache.config.ConfigurationHelper# No CacheExceptionHandlerFactory class specified. Skipping...
::31.559 INFO alibaba.dubbo.registry.zookeeper.ZookeeperRegistry# [DUBBO] Load registry store file /home/tomcat/.dubbo/dubb
::31.572 DEBUG org.I0Itec.zkclient.ZkConnection# Creating new ZookKeeper instance to connect to 192.168.35.2:.
::31.578 INFO org.I0Itec.zkclient.ZkEventThread# Starting ZkClient event thread.
::31.584 INFO org.apache.zookeeper.ZooKeeper# Client environment:zookeeper.version=3.4.-, built on // : GMT
::31.584 INFO org.apache.zookeeper.ZooKeeper# Client environment:host.name=iZ25iig1og4Z
::31.584 INFO org.apache.zookeeper.ZooKeeper# Client environment:java.version=1.7.0_80
::31.584 INFO org.apache.zookeeper.ZooKeeper# Client environment:java.vendor=Oracle Corporation
::31.585 INFO org.apache.zookeeper.ZooKeeper# Client environment:java.home=/opt/java/jdk1..0_80/jre
::31.585 INFO org.apache.zookeeper.ZooKeeper# Client environment:java.class.path=/opt/tomcat/apache-tomcat-7.0./bin/bootstrap.jar:/opt/tomcat/apache-tomcat-7.0./bin/tomcat-juli.jar
::31.585 INFO org.apache.zookeeper.ZooKeeper# Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
::31.585 INFO org.apache.zookeeper.ZooKeeper# Client environment:java.io.tmpdir=/home/tomcat/tomcat7_jdk7_2/temp
::31.585 INFO org.apache.zookeeper.ZooKeeper# Client environment:java.compiler=<NA>
::31.586 INFO org.apache.zookeeper.ZooKeeper# Client environment:os.name=Linux
::31.586 INFO org.apache.zookeeper.ZooKeeper# Client environment:os.arch=amd64
::31.586 INFO org.apache.zookeeper.ZooKeeper# Client environment:os.version=2.6.-431.23..el6.x86_64
::31.586 INFO org.apache.zookeeper.ZooKeeper# Client environment:user.name=tomcat
::31.586 INFO org.apache.zookeeper.ZooKeeper# Client environment:user.home=/home/tomcat
::31.586 INFO org.apache.zookeeper.ZooKeeper# Client environment:user.dir=/opt/tomcat/apache-tomcat-7.0./bin
::31.587 INFO org.apache.zookeeper.ZooKeeper# Initiating client connection, connectString=192.168.35.2: sessionTimeout= watcher=org.I0Itec.zkclient.ZkClient@3c4ff559
::31.602 DEBUG org.I0Itec.zkclient.ZkClient# Awaiting connection to Zookeeper server
::31.606 DEBUG org.I0Itec.zkclient.ZkClient# Waiting for keeper state SyncConnected
::31.608 INFO org.apache.zookeeper.ClientCnxn# Opening socket connection to server 192.168.35.2/192.168.35.2:. Will not attempt to authenticate using SASL (unknown error)
::31.614 INFO org.apache.zookeeper.ClientCnxn# Socket connection established to 192.168.35.2/192.168.35.2:, initiating session
::31.625 INFO org.apache.zookeeper.ClientCnxn# Session establishment complete on server 192.168.35.2/192.168.35.2:, sessionid = 0x151de41a1800146, negotiated timeout =
::31.627 DEBUG org.I0Itec.zkclient.ZkClient# Received event: WatchedEvent state:SyncConnected type:None path:null
::31.627 INFO org.I0Itec.zkclient.ZkClient# zookeeper state changed (SyncConnected)
::31.627 DEBUG org.I0Itec.zkclient.ZkClient# Leaving process event
::31.627 DEBUG org.I0Itec.zkclient.ZkClient# State is SyncConnected
::31.681 INFO alibaba.dubbo.registry.zookeeper.ZookeeperRegistry# [DUBBO] Register: consumer://192.168.35.2/com.rockbb.credipay...
::31.726 INFO alibaba.dubbo.registry.zookeeper.ZookeeperRegistry# [DUBBO] Subscribe: consumer://192.168.35.2/com.rockbb.credipay...
::31.751 INFO alibaba.dubbo.registry.zookeeper.ZookeeperRegistry# [DUBBO] Notify urls for subscribe url consumer://192.168.35.2/com.rockbb.credipay...
::31.776 WARN ework.web.context.support.XmlWebApplicationContext# Exception encountered during context initialization - cancelling refresh attempt
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'marketTask': Injection of autowired dependencies failed; nested exception is org.springframework.beans.factory.BeanCreationException: Could not autowire field: private com.rockbb.credipay.commons.api.service.DayInterestService com.rockbb.credipay.daemon.task.MarketTask.dayInterestService; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dayInterestService': FactoryBean threw exception on object creation; nested exception is java.lang.IllegalStateException: Failed to check the status of the service com.rockbb.credipay.commons.api.service.DayInterestService. No provider available for the service com.rockbb.credipay.commons.api.service.DayInterestService from the url zookeeper://192.168.35.2:2181/com.alibaba.dubbo.registry.RegistryService?application=celt-daemon-machine&default.version=develop-machine&dubbo=2.5.3&interface=com.rockbb.credipay.commons.api.service.DayInterestService&methods=update,count,batchUpdate,select,list,doVirtualCapitalInterest,insert,selectVirtualCapitalInterest&pid=26624&revision=1.0-SNAPSHOT&side=consumer×tamp=1464788911437 to the consumer 192.168.35.2 use dubbo version 2.5.3
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessPropertyValues(AutowiredAnnotationBeanPostProcessor.java:) ~[spring-beans-4.1..RELEASE.jar:4.1..RELEASE]
从最后几行的日志中可以看到, 在Dubbo注册后, 初始化SpringContext的过程中出现了错误, 导致初始化失败.
但zkClient线程还是正常启动, zookeeper服务器重启,zkClient开始重连,连接上zookeeper服务器;
zkClient触发watch的一些代码,ClassLoader尝试加载org/apache/zookeeper/proto/SetWatches类,但是发现找不到类,于是抛出异常;
zkClient捕获到异常,认为重连失败,close掉connection,休眠几秒之后,再次重连;
于是出现了zkClient反复重试连接zookeeper服务器的情况
要避免这种问题: 不能在dubbo消费端正在启动的时候, 关闭/重启所有可用的服务端.