墨菲定律:当你觉得一个地方可能有bug,那么这个地方就会有bug----顺带了解下Tomcat那少有人注意的localhost.log
2019-12-02

一、问题概述

题目有点长,但应该值得后端java们了解下有点小坑的localhost.log,让我长话短说。

博主是搞java后端的。后台是很简单的spring mvc + spring框架。

今天测试一个Controller层的接口,但是断点一直进不来。

我做的改动也不大,新增了mqMsgFactoryUtils这个spring 托管的bean,(代码是接手别人的,所以看着原来的部分有点臃肿,就提炼了mqMsgFactoryUtils公共类

,mqMsgFactoryUtils需要依赖bean,就把自己也搞成bean了)。

如下:

 

 

 断点进不来怎么办,作为一个工作了几年的老司机,思路还是清晰的,直接在filter打断点,发现可以进来。

然后在aop层打断点,aop层有个切controller层方法的@before方法,主要是一些额外的参数校验。

在aop层的断点里,代码走到如下位置,return了:

 

因为这个类也是刚被我重构的,我一想,难道是用了return后,像spring的拦截器一样,直接把request返回了吗?

 

于是我把针对这个aop类的修改回退了,结果发现问题还是存在。

这就神了,filter正常,对aop的修改也回退了,然而controller还是进不去。

 

二、问题原因

经过上面一番折腾了,午睡是没了,很困,暂时没什么思路。然后又发起了一次request,发现问题还是那样。

但是,这次,我点开了下面的日志:(图片小的话,可以在新的tab打开就清晰了)

 

哈?这里还有个日志?一看还真就和该问题有关系。

至此,真相大白。

之前刚接手这份代码时,我就很奇怪为什么很多controller头上要搞个这:

 

当时感觉新接手代码,觉得“一切都是有因有果”,可能是之前的哥们觉得这个controller类有可能有并发问题,线程同步问题啥的。

加就加吧,我又不动它。虽然感觉有点和以前不一样,但应该没啥大问题。无非是controller不是单例罢了。

多创建几个没什么大不了。

以上就是我之前的心态。直到这次遇到这个问题。

 

有些同学估计没懂,我这里解释下,当controller加了prototype后,就不会在应用启动时就将该controller 单例bean创建好,而是等到需要的时候再去创建。

什么时候是需要的时候呢,就是请求进来,经spring mvc的handlerMappingAdapter分析,需要路由到该controller时,发现该bean的bean definition的scope为prototype,

就会去创建该controller。

创建的时候,就该注入各service了。但是恰好,这个service的包没在扫描范围内(我单独加了个包,然后我们的配置文件不是配置成只扫描base package的,是扫描一系列的具体package)。

那么,没扫描到这个bean,依赖不满足,当然,这个controller就创建失败了。

于是抛异常。

 

三、异常日志为啥打这儿呢

接着说问题。原因清楚了之后,我又试了一遍:去掉prototype,重启应用,果然,这次启动失败了。

然后,大家估计有疑问了,你有异常,日志打这个localhost.log是什么意思,一般人(比如我),主要关注的是应用的console输出面板。

我就想,这个异常信息,打到这个文件?为什么?这个文件干嘛的?

查了点资料,发现google比百度资料还少点。。。将就看吧。

localhost.{yyyy-MM-dd}.log主要是应用初始化(listener, filter, servlet)未处理的异常最后被tomcat捕获而输出的日志 

这么说,这是spring 创建bean失败,直接向tomcat抛出了异常。这下面是堆栈。

02-Nov-2018 16:36:17.882 严重 [http-nio-8080-exec-4] org.apache.catalina.core.ApplicationDispatcher.invoke Servlet.service() for servlet [DispatcherServlet] threw exception org.springframework.beans.factory.NoSuchBeanDefinitionException: No qualifying bean of type "com.ceiec.service.mqmsg.MqMsgFactoryUtils" available: expected at least 1 bean which qualifies as autowire candidate. Dependency annotations: {@org.springframework.beans.factory.annotation.Autowired(required=true)} at org.springframework.beans.factory.support.DefaultListableBeanFactory.raiseNoMatchingBeanFound(DefaultListableBeanFactory.java:1486) at org.springframework.beans.factory.support.DefaultListableBeanFactory.doResolveDependency(DefaultListableBeanFactory.java:1104) at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveDependency(DefaultListableBeanFactory.java:1066) at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor$AutowiredFieldElement.inject(AutowiredAnnotationBeanPostProcessor.java:585) at org.springframework.beans.factory.annotation.InjectionMetadata.inject(InjectionMetadata.java:88) at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessPropertyValues(AutowiredAnnotationBeanPostProcessor.java:366) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1264) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:553) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483) at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:325) at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197) at org.springframework.web.method.HandlerMethod.createWithResolvedBean(HandlerMethod.java:259) at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.getHandlerInternal(AbstractHandlerMethodMapping.java:323) at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.getHandlerInternal(AbstractHandlerMethodMapping.java:61) at org.springframework.web.servlet.handler.AbstractHandlerMapping.getHandler(AbstractHandlerMapping.java:352) at org.springframework.web.servlet.DispatcherServlet.getHandler(DispatcherServlet.java:1156) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:936) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) at javax.servlet.http.HttpServlet.service(HttpServlet.java:661) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:728) at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:467) at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:392) at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:311) at com.ceiec.webservice.filter.WebRequestFilter.doFilterInternal(WebRequestFilter.java:116) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346) at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.orm.hibernate4.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:151) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748)

 

刚开始,我感觉是不是spring这么处理有点不对,直接将异常抛给tomcat。但是转念一想,启动时,创建bean失败的话,也是会直接抛给tomcat,tomcat抛给用户来处理。

这么一想,可以理解。但是还是感觉:为啥不能在应用里打个日志呢?打个日志,起码一下就找到问题了。

 

四、关于tomcat的日志

这里只简单介绍下几种日志吧。

catalina.out,这个大家都知道,stdout和stderr都会打到这。(也就是应用的System.out.println,以及tomcat自己的stdout和stderr)

然后是logs目录下的另外几种日志,其中,红色箭头指向的,很重要(当然,以前只觉得localhost_access.log重要,经过今天这一课嘛。。。):

 

这几个日志在哪配置的呢?

一般在tomcat安装目录下的conf下的logging.properties.

 

但是,tomcat这么完备的服务器,不可能这么easy。

实际是这样的,(来自于官方文档,链接会在最后给出来):

1、全局模式:

那就是catalina.base下的conf下的logging.properties了,也可以通过启动时通过java.util.logging.config.file来指定。如果该文件不可读或没配置,会使用javahome下的lib下的该文件。

2、在应用中,默认位于WEB-INF/classes/logging.properties.

 

Tomcat默认的日志框架为juli。基于java.util.logging改的。也可以换成log4j,操作不繁琐,链接如下:

https://tomcat.apache.org/tomcat-8.0-doc/logging.html#Using_Log4j

 

 五、心得体会

这里,让我们再次记得:如果出了bug,记得看看localhost.log。

 

参考了:

tomcat日志 之 catalina.log & localhost.log

 https://tomcat.apache.org/tomcat-8.0-doc/logging.html#