Dubbo消费端错误: ClassNotFoundException: org.apache.zookeeper.proto.WatcherEvent
出现错误的原因是消费端war没有启动成功, 但是zkClient和Dubbo的对应Thread启动了, web container无法加载对应的类,
INFO: Initializing ProtocolHandler ["http-bio-8081"] Jun 01, 2016 9:48:24 PM org.apache.coyote.AbstractProtocol init INFO: Initializing ProtocolHandler ["ajp-bio-8010"] Jun 01, 2016 9:48:24 PM org.apache.catalina.startup.Catalina load INFO: Initialization processed in 773 ms Jun 01, 2016 9:48:24 PM org.apache.catalina.core.StandardService startInternal INFO: Starting service Catalina Jun 01, 2016 9:48:24 PM org.apache.catalina.core.StandardEngine startInternal INFO: Starting Servlet Engine: Apache Tomcat/7.0.67 Jun 01, 2016 9:48:24 PM org.apache.catalina.startup.HostConfig deployWAR INFO: Deploying web application archive /home/tomcat/tomcat7_jdk7_2/webapps/daemon.war Jun 01, 2016 9:48:28 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 01, 2016 9:48:31 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 01, 2016 9:48:31 PM org.apache.catalina.core.StandardContext startInternal SEVERE: Context [/daemon] startup failed due to previous errors Jun 01, 2016 9:48:31 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads SEVERE: The web application [/daemon] appears to have started a thread named [DubboRegistryFailedRetryTimer-thread-1] but has failed to stop it. This is very likely to create a memory leak. Jun 01, 2016 9:48:31 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
然后在接下来的日志中
INFO: Starting ProtocolHandler ["http-bio-8081"] Jun 01, 2016 9:48:32 PM org.apache.coyote.AbstractProtocol start INFO: Starting ProtocolHandler ["ajp-bio-8010"] Jun 01, 2016 9:48:32 PM org.apache.catalina.startup.Catalina start INFO: Server startup in 7382 ms Jun 01, 2016 9:48:46 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:1747)
而Dubbo消费端未启动的原因, 是Spring初始化失败
160601 21:48:29.725 INFO org.springframework.web.context.ContextLoader#285 Root WebApplicationContext: initialization started 160601 21:48:29.867 INFO ework.web.context.support.XmlWebApplicationContext#510 Refreshing Root WebApplicationContext: startup date [Wed Jun 01 21:48:29 CST 2016]; root of context hierarchy 160601 21:48:29.917 INFO ramework.beans.factory.xml.XmlBeanDefinitionReader#317 Loading XML bean definitions from class path resource [spring/spring-daemon.xml] 160601 21:48:30.232 INFO ramework.beans.factory.xml.XmlBeanDefinitionReader#317 Loading XML bean definitions from class path resource [spring/spring-daemon-dubbo.xml] 160601 21:48:30.316 INFO com.alibaba.dubbo.common.logger.LoggerFactory#58 using logger: com.alibaba.dubbo.common.logger.log4j.Log4jLoggerAdapter 160601 21:48:30.561 INFO beans.factory.config.PropertyPlaceholderConfigurer#172 Loading properties file from class path resource [application.properties] 160601 21:48:30.634 INFO work.scheduling.concurrent.ThreadPoolTaskScheduler#165 Initializing ExecutorService 'myScheduler' 160601 21:48:30.634 INFO essorRegistrationDelegate$BeanPostProcessorChecker#309 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) 160601 21:48:30.661 INFO gframework.cache.ehcache.EhCacheManagerFactoryBean#129 Initializing EhCache CacheManager 160601 21:48:30.664 DEBUG net.sf.ehcache.config.ConfigurationFactory#150 Configuring ehcache from InputStream 160601 21:48:30.677 DEBUG net.sf.ehcache.config.DiskStoreConfiguration#141 Disk Store Path: /home/tomcat/tomcat7_jdk7_2/temp 160601 21:48:30.702 DEBUG net.sf.ehcache.util.PropertyUtil#88 propertiesString is null. 160601 21:48:30.713 DEBUG net.sf.ehcache.config.ConfigurationHelper#185 No CacheManagerEventListenerFactory class specified. Skipping... 160601 21:48:30.729 DEBUG net.sf.ehcache.Cache#955 No BootstrapCacheLoaderFactory class specified. Skipping... 160601 21:48:30.729 DEBUG net.sf.ehcache.Cache#929 CacheWriter factory not configured. Skipping... 160601 21:48:30.731 DEBUG net.sf.ehcache.config.ConfigurationHelper#96 No CacheExceptionHandlerFactory class specified. Skipping... 160601 21:48:31.559 INFO alibaba.dubbo.registry.zookeeper.ZookeeperRegistry#58 [DUBBO] Load registry store file /home/tomcat/.dubbo/dubb 160601 21:48:31.572 DEBUG org.I0Itec.zkclient.ZkConnection#63 Creating new ZookKeeper instance to connect to 192.168.35.2:2181. 160601 21:48:31.578 INFO org.I0Itec.zkclient.ZkEventThread#64 Starting ZkClient event thread. 160601 21:48:31.584 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:zookeeper.version=3.4.6-1569965, built on 02/20/2014 09:09 GMT 160601 21:48:31.584 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:host.name=iZ25iig1og4Z 160601 21:48:31.584 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:java.version=1.7.0_80 160601 21:48:31.584 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:java.vendor=Oracle Corporation 160601 21:48:31.585 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:java.home=/opt/java/jdk1.7.0_80/jre 160601 21:48:31.585 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:java.class.path=/opt/tomcat/apache-tomcat-7.0.67/bin/bootstrap.jar:/opt/tomcat/apache-tomcat-7.0.67/bin/tomcat-juli.jar 160601 21:48:31.585 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib 160601 21:48:31.585 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:java.io.tmpdir=/home/tomcat/tomcat7_jdk7_2/temp 160601 21:48:31.585 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:java.compiler=<NA> 160601 21:48:31.586 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:os.name=Linux 160601 21:48:31.586 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:os.arch=amd64 160601 21:48:31.586 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:os.version=2.6.32-431.23.3.el6.x86_64 160601 21:48:31.586 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:user.name=tomcat 160601 21:48:31.586 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:user.home=/home/tomcat 160601 21:48:31.586 INFO org.apache.zookeeper.ZooKeeper#100 Client environment:user.dir=/opt/tomcat/apache-tomcat-7.0.67/bin 160601 21:48:31.587 INFO org.apache.zookeeper.ZooKeeper#438 Initiating client connection, connectString=192.168.35.2:2181 sessionTimeout=30000 watcher=org.I0Itec.zkclient.ZkClient@3c4ff559 160601 21:48:31.602 DEBUG org.I0Itec.zkclient.ZkClient#893 Awaiting connection to Zookeeper server 160601 21:48:31.606 DEBUG org.I0Itec.zkclient.ZkClient#643 Waiting for keeper state SyncConnected 160601 21:48:31.608 INFO org.apache.zookeeper.ClientCnxn#975 Opening socket connection to server 192.168.35.2/192.168.35.2:2181. Will not attempt to authenticate using SASL (unknown error) 160601 21:48:31.614 INFO org.apache.zookeeper.ClientCnxn#852 Socket connection established to 192.168.35.2/192.168.35.2:2181, initiating session 160601 21:48:31.625 INFO org.apache.zookeeper.ClientCnxn#1235 Session establishment complete on server 192.168.35.2/192.168.35.2:2181, sessionid = 0x151de41a1800146, negotiated timeout = 30000 160601 21:48:31.627 DEBUG org.I0Itec.zkclient.ZkClient#351 Received event: WatchedEvent state:SyncConnected type:None path:null 160601 21:48:31.627 INFO org.I0Itec.zkclient.ZkClient#449 zookeeper state changed (SyncConnected) 160601 21:48:31.627 DEBUG org.I0Itec.zkclient.ZkClient#395 Leaving process event 160601 21:48:31.627 DEBUG org.I0Itec.zkclient.ZkClient#653 State is SyncConnected 160601 21:48:31.681 INFO alibaba.dubbo.registry.zookeeper.ZookeeperRegistry#58 [DUBBO] Register: consumer://192.168.35.2/com.rockbb.credipay... 160601 21:48:31.726 INFO alibaba.dubbo.registry.zookeeper.ZookeeperRegistry#58 [DUBBO] Subscribe: consumer://192.168.35.2/com.rockbb.credipay... 160601 21:48:31.751 INFO alibaba.dubbo.registry.zookeeper.ZookeeperRegistry#58 [DUBBO] Notify urls for subscribe url consumer://192.168.35.2/com.rockbb.credipay... 160601 21:48:31.776 WARN ework.web.context.support.XmlWebApplicationContext#487 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:334) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
从最后几行的日志中可以看到, 在Dubbo注册后, 初始化SpringContext的过程中出现了错误, 导致初始化失败.
但zkClient线程还是正常启动, zookeeper服务器重启，zkClient开始重连，连接上zookeeper服务器；
zkClient触发watch的一些代码，ClassLoader尝试加载org/apache/zookeeper/proto/SetWatches类，但是发现找不到类，于是抛出异常；
zkClient捕获到异常，认为重连失败，close掉connection，休眠几秒之后，再次重连；
于是出现了zkClient反复重试连接zookeeper服务器的情况
要避免这种问题: 不能在dubbo消费端正在启动的时候, 关闭/重启所有可用的服务端.
