背景:一个刚开发完的小项目部署到测试环境,总是部署失败,直观的报错是error日志中有dubbo端口被占用。项目为springmvc框架+tomcat。
错误日志为:
[0518 19:36:41 354 ERROR] [main] web.context.ContextLoader - Context initialization failed
com.alibaba.dubbo.rpc.RpcException: Fail to start server(url: dubbo://192.168.1.121:18191/com.tongbanjie.security.facade.api.AuthCodeValidationFacade?
anyhost=true&application=security&channel.readonly.sent=true&codec=dubbo&default.retries=0&default.timeout=30000&dubbo=2.5.3&heartbeat=60000&interface
=com.tongbanjie.security.facade.api.AuthCodeValidationFacade&methods=verifyAuthCode&pid=16819&revision=1.0-SNAPSHOT&side=provider×tamp=1463571401
299&version=2.0) Failed to bind NettyServer on /192.168.1.121:18191, cause: Failed to bind to: /0.0.0.0:18191
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol.createServer(DubboProtocol.Java:289)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol.openServer(DubboProtocol.java:266)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol.export(DubboProtocol.java:253)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper.export(ProtocolFilterWrapper.java:55)
at com.alibaba.dubbo.rpc.protocol.ProtocolListenerWrapper.export(ProtocolListenerWrapper.java:56)
at com.alibaba.dubbo.rpc.Protocol$Adpative.export(Protocol$Adpative.java)
at com.alibaba.dubbo.registry.integration.RegistryProtocol.doLocalExport(RegistryProtocol.java:153)
at com.alibaba.dubbo.registry.integration.RegistryProtocol.export(RegistryProtocol.java:107)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper.export(ProtocolFilterWrapper.java:53)
at com.alibaba.dubbo.rpc.protocol.ProtocolListenerWrapper.export(ProtocolListenerWrapper.java:54)
at com.alibaba.dubbo.rpc.Protocol$Adpative.export(Protocol$Adpative.java)
at com.alibaba.dubbo.config.ServiceConfig.doExportUrlsFor1Protocol(ServiceConfig.java:485)
at com.alibaba.dubbo.config.ServiceConfig.doExportUrls(ServiceConfig.java:281)
at com.alibaba.dubbo.config.ServiceConfig.doExport(ServiceConfig.java:242)
at com.alibaba.dubbo.config.ServiceConfig.export(ServiceConfig.java:143)
at com.alibaba.dubbo.config.spring.ServiceBean.onApplicationEvent(ServiceBean.java:109)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:96)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:334)
at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:948)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:482)
at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:410)
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4210)
at org.apache.catalina.core.StandardContext.start(StandardContext.java:4709)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:799)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:779)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:583)
at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1079)
at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:1002)
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:506)
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1317)
at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:324)
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:142)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1065)
at org.apache.catalina.core.StandardHost.start(StandardHost.java:822)
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1057)
at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:463)
at org.apache.catalina.core.StandardService.start(StandardService.java:525)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:754)
at org.apache.catalina.startup.Catalina.start(Catalina.java:595)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.apache.commons.daemon.support.DaemonLoader.start(DaemonLoader.java:243)
Caused by: com.alibaba.dubbo.remoting.RemotingException: Failed to bind NettyServer on /192.168.1.121:18191, cause: Failed to bind to: /0.0.0.0:18191
at com.alibaba.dubbo.remoting.transport.AbstractServer.<init>(AbstractServer.java:72)
at com.alibaba.dubbo.remoting.transport.netty.NettyServer.<init>(NettyServer.java:63)
at com.alibaba.dubbo.remoting.transport.netty.NettyTransporter.bind(NettyTransporter.java:33)
at com.alibaba.dubbo.remoting.Transporter$Adpative.bind(Transporter$Adpative.java)
at com.alibaba.dubbo.remoting.Transporters.bind(Transporters.java:48)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchanger.bind(HeaderExchanger.java:41)
at com.alibaba.dubbo.remoting.exchange.Exchangers.bind(Exchangers.java:63)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol.createServer(DubboProtocol.java:287)
... 50 more
Caused by: org.jboss.netty.channel.ChannelException: Failed to bind to: /0.0.0.0:18191
at org.jboss.netty.bootstrap.ServerBootstrap.bind(ServerBootstrap.java:303)
at com.alibaba.dubbo.remoting.transport.netty.NettyServer.doOpen(NettyServer.java:94)
at com.alibaba.dubbo.remoting.transport.AbstractServer.<init>(AbstractServer.java:67)
... 57 more
Caused by: java.net.BindException: 地址已在使用
at sun.nio.ch.Net.bind0(Native Method)
at sun.nio.ch.Net.bind(Net.java:344)
at sun.nio.ch.Net.bind(Net.java:336)
at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:199)
at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.bind(NioServerSocketPipelineSink.java:148)
at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleServerSocket(NioServerSocketPipelineSink.java:100)
at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:74)
at org.jboss.netty.channel.Channels.bind(Channels.java:468)
at org.jboss.netty.channel.AbstractChannel.bind(AbstractChannel.java:192)
at org.jboss.netty.bootstrap.ServerBootstrap$Binder.channelOpen(ServerBootstrap.java:348)
at org.jboss.netty.channel.Channels.fireChannelOpen(Channels.java:176)
at org.jboss.netty.channel.socket.nio.NioServerSocketChannel.<init>(NioServerSocketChannel.java:85)
at org.jboss.netty.channel.socket.nio.NioServerSocketChannelFactory.newChannel(NioServerSocketChannelFactory.java:142)
at org.jboss.netty.channel.socket.nio.NioServerSocketChannelFactory.newChannel(NioServerSocketChannelFactory.java:90)
at org.jboss.netty.bootstrap.ServerBootstrap.bind(ServerBootstrap.java:282)
... 59 more
首先想到是看看什么占用了18191端口:
[root@centos02 app]# netstat -tunlp|grep 18191
tcp 0 0 :::18191 :::* LISTEN 23049/jsvc.exec
[root@centos02 app]# ps -ef|grep 23049
tomcat 23049 23048 0 May18 ? 00:04:14 jsvc.exec -java-home /usr/java/jdk1.7.0_04 -user tomcat ......
占用18191的就是部署这个应用的tomcat实例。
kill -9 干掉实例,重启,一样报错。
同事换了个端口28191,还是报类似的错误,只是变成了28191端口被占用。
error日志只有端口被占用一条错误信息,那就看看其他日志。
tomcat日志,catalina.log:
五月 18, 2016 7:36:36 下午 org.apache.catalina.loader.WebappClassLoader validateJarFile
信息: validateJarFile(/data/www/ROOT/security/security/WEB-INF/lib/servlet-api-2.5.jar) - jar not loaded. See Servlet Spec 2.3, section 9.7.2. Offendi
ng class: javax/servlet/Servlet.class
五月 18, 2016 7:36:41 下午 org.apache.catalina.core.StandardContext start
严重: Error listenerStart
五月 18, 2016 7:36:41 下午 org.apache.catalina.core.StandardContext start
严重: Context [/security] startup failed due to previous errors
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesJdbc
严重: The web application [/security] registered the JDBC driver [com.alibaba.druid.proxy.DruidDriver] but failed to unregister it when the web applic
ation was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesJdbc
严重: The web application [/security] registered the JDBC driver [com.MySQL.jdbc.Driver] but failed to unregister it when the web application was stop
ped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
严重: The web application [/security] 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.
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
严重: The web application [/security] appears to have started a thread named [ZkClient-EventThread-69-zk.tbj.com:2181] but has failed to stop it. This
is very likely to create a memory leak.
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
严重: The web application [/security] appears to have started a thread named [main-SendThread(zk.tbj.com:2181)] but has failed to stop it. This is ver
y likely to create a memory leak.
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
严重: The web application [/security] appears to have started a thread named [main-EventThread] but has failed to stop it. This is very likely to crea
te a memory leak.
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
严重: The web application [/security] appears to have started a thread named [DubboSaveRegistryCache-thread-1] but has failed to stop it. This is very
likely to create a memory leak.
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
严重: The web application [/security] appears to have started a thread named [DubboClientReconnectTimer-thread-1] but has failed to stop it. This is v
ery likely to create a memory leak.
五月 18, 2016 7:36:41 下午 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
严重: The web application [/security] appears to have started a thread named [NettyClientBoss-thread-1] but has failed to stop it. This is very likely
to create a memory leak.
其中:
五月 18, 2016 7:36:41 下午 org.apache.catalina.core.StandardContext start
严重: Error listenerStart
五月 18, 2016 7:36:41 下午 org.apache.catalina.core.StandardContext start
严重: Context [/security] startup failed due to previous errors
结合error日志时间点,应该是dubbo端口占用导致spring启动失败,从而此处报错。上边还有一个错误信息:
五月 18, 2016 7:36:36 下午 org.apache.catalina.loader.WebappClassLoader validateJarFile
信息: validateJarFile(/data/www/ROOT/security/security/WEB-INF/lib/servlet-api-2.5.jar) - jar not loaded. See Servlet Spec 2.3, section 9.7.2. Offendi
ng class: javax/servlet/Servlet.class
这个应该是应用打的包中包含servlet.jar,解决办法是在maven中把这个包的scope设置为provided,这个应该不是导致我们启动失败的原因。那么究竟是什么导致dubbo端口被占用的呢??
继续找日志,tomcat日志,应用的error日志,都已经看了,那只剩下应用的info日志了。没办法大量的info日志,一条一条读吧。
还真让我发现了问题!!
0518 21:00:04 679 INFO ] [main] web.context.ContextLoader - Root WebApplicationContext: initialization started
[0518 21:00:04 868 INFO ] [main] context.support.XmlWebApplicationContext - Refreshing Root WebApplicationContext: startup date [Wed May 18 21:00:04 C
ST 2016]; root of context hierarchy
[0518 21:00:05 021 INFO ] [main] factory.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/spring/security
-context.xml]
.........
[0518 21:00:12 567 INFO ] [main] web.servlet.DispatcherServlet - FrameworkServlet 'springmvc': initialization completed in 1209 ms
[0518 21:00:15 330 INFO ] [main] web.context.ContextLoader - Root WebApplicationContext: initialization started
[0518 21:00:15 434 INFO ] [main] context.support.XmlWebApplicationContext - Refreshing Root WebApplicationContext: startup date [Wed May 18 21:00:15 C
ST 2016]; root of context hierarchy
..........
Root WebApplicationContext 启动了两次,第二次报错了,容器关闭。启动两次,这就可以理解为什么dubbo端口怎么改都会被占用了。那么问题来了,为什么会启动两次呢?本地跑是正常的呀。
比较了应用配置,和其他能够正常启动的应用也是一样的。
就随便看看tomcat配置吧,比较下同一台测试机器上的两个应用,一个是有问题的,一个是正常的。
还真不太一样,在server.xml:
正常的:
<Host name="localhost" debug="0" appBase="/data/www/ROOT/xxx"
unpackWARs="true" autoDeploy="false" deployOnStartup="false"
xmlValidation="false" xmlNamespaceAware="false" >
<Context path="" docBase="xxxxx" debug="0" reloadable="false"/>
</Host>
不正常的:
<Host name="localhost" debug="0" appBase="/data/www/ROOT/xxx"
unpackWARs="true" autoDeploy="true" deployOnStartup="true"
xmlValidation="false" xmlNamespaceAware="false" >
<Context path="" docBase="xxxxx" debug="0" reloadable="false"/>
</Host>
这两个配置不知道具体什么含义,先改成和正常的一样试试吧。
改了,还真就正常了,spring context只启动一次,dubbo端口也不再被占用。
那么下边来查查tomcat server.xml中,autoDeploy和deployOnStartup的含义。
摘抄:
http://www.cnblogs.com/ywl925/archive/2013/02/28/2936926.html
autoDeploy:如果此项设为true,表示Tomcat服务处于运行状态时,能够监测appBase下的文件,如果有新有web应用加入进来,会自运发布这个WEB应用
unpackWARs:如果此项设置为true,表示把WEB应用的WAR文件先展开为开放目录结构后再运行.如果设为false将直接运行为WAR文件
deployOnStartup:如果此项设为true,表示Tomcat服务器启动时会自动发布appBase目录下所有的Web应用.如果Web应用中的server.xml没有相应的<Context>元素,将采用Tomcat默认的Context
http://kalogen.iteye.com/blog/910326
如果将autoDeploy设置为true,就会发生再次部署的现象,第一次因server.xml中的Context配置而被部署(因为deployOnstartup="true "),
而第二次因autoDeploy被设置为true而发生自动部署(默认情况下,在没有显式Context的这些属性时,它们每个的默认值都是true)。
显式设置autoDeploy为False。避免了在server.xml中增加Context配置时两次部署相同的Web应用程序。
先了解这一点,知道这个的存在吧。
google找到的一篇相关文章:http://www.android100.org/html/201604/23/232027.html
接下来,
应用启动是正常了,但是在我们自己的应用管理工具上看到的应用还是没有启动成功。???
还是和正常的应用比较,应用web-inf目录下缺少status.jsp文件,这个文件的内容是ok两个字母,想想应用管理工具可能是通过访问这个jsp文件来测试
应用是否启动成功的。
加上去,应用管理工具还是现实没有启动成功。
在浏览器中访问这个jsp文件,竟然访问不到,这个好办,检查下web.xml看看有没有被拦截就知道了。
<servlet> <servlet-name>springmvc</servlet-name> <servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class> <init-param> <param-name>contextConfigLocation</param-name> <param-value>classpath:/META-INF/spring/security-mvc.xml</param-value> </init-param> <load-on-startup>1</load-on-startup> </servlet> <servlet-mapping> <servlet-name>springmvc</servlet-name> <url-pattern>/*</url-pattern> </servlet-mapping>这总么行,所有访问都被springmvc拦截了。
改成
<servlet-mapping> <servlet-name>springmvc</servlet-name> <url-pattern>/</url-pattern> </servlet-mapping>就ok了,status.jsp就能够正常访问了。
那么"/* "和 “/”这两个url-pattern的区别是什么呢?
以下为摘抄:
/* 匹配所有请求,自然包括/status.jsp;
/ 作为默认servlet,当应用中找不到路径才会进来,web.xml默认会有jsp支持,根据jsp的文件名来匹配请求,那么访问/status.jsp能够找到对应web-inf下边status.jsp生成的servlet。
ok,今天这个问题是解决了。
注意点:
1.还是遇到问题,先日志,不仅是error日志,各个日志都可能有帮助信息。
2.还是google,但是要找到正确的搜索点,比如这次遇到的问题,我搜dubbo地址被占用相关的关键词,劈天盖地,也找不到想要的答案;在分析info日志,
判断出来spring context启动两次后(这才是真正的原因),很快能够找到相关性大一点的网