Dubbo消费端错误: ClassNotFoundException: org.apache.zookeeper.proto.WatcherEvent

Posted 2020-07-19 Milton

出现错误的原因是消费端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=[email protected]
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&timestamp=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消费端正在启动的时候, 关闭/重启所有可用的服务端.