Spring Boot和Tomcat的启动日志源码调用剖析
2017-08-31 本文已影响355人
简放视野
分析Spring Boot启动和关闭的info级别的日志和IDE debug调试来熟悉Spring Boot和Spring Framework在启动和关闭整个过程中的工作，对Spring框架整体有所理解。(完成第一遍剖析后，可以基于debug级别的日志做进一步细粒度的调用剖析)
## SpringApplication.run(Object, String...) -> SpringApplication.run(Object[], String[]) -> SpringApplication.run(String...)
## -> SpringApplication.printBanner -> SpringApplicationBannerPrinter.print(Environment, Class<?>, PrintStream)
## -> SpringApplicationBannerPrinter.getBanner -> SpringBootBanner.printBanner(横幅)
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v1.5.4.RELEASE)
## SpringApplication.run(String...)
## -> SpringApplication.prepareContext -> SpringApplication.logStartupInfo
## -> StartupInfoLogger.logStarting(Log) -> StartupInfoLogger.getStartupMessage
2017-07-09 22:16:34.026 INFO 26314 --- [ main] spring.guides.hello.GreetingApplication : Starting GreetingApplication on 192.168.1.3 with PID 26314 (/Users/dannong/Documents/workspace/GitHub/spring-guides/gs-rest-service/target/classes started by dannong in /Users/dannong/Documents/workspace/GitHub/spring-guides)
## SpringApplication.prepareContext
## -> SpringApplication.logStartupProfileInfo
2017-07-09 22:16:34.040 INFO 26314 --- [ main] spring.guides.hello.GreetingApplication : No active profile set, falling back to default profiles: default
# ================= 核心流程 =================
## SpringApplication.run(String...)
## -> SpringApplication.refreshContext -> SpringApplication.refresh(ApplicationContext)
## -> EmbeddedWebApplicationContext.refresh -> AbstractApplicationContext.refresh
## -> AnnotationConfigEmbeddedWebApplicationContext.prepareRefresh -> AbstractApplicationContext.prepareRefresh
## -> AbstractApplicationContext.toString
2017-07-09 22:16:34.200 INFO 26314 --- [ main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@5e25a92e: startup date [Sun Jul 09 22:16:34 CST 2017]; root of context hierarchy
## AbstractApplicationContext.refresh
## -> EmbeddedWebApplicationContext.onRefresh -> EmbeddedWebApplicationContext.createEmbeddedServletContainer
## -> TomcatEmbeddedServletContainerFactory.getEmbeddedServletContainer -> TomcatEmbeddedServletContainerFactory.getTomcatEmbeddedServletContainer(Tomcat)
## -> TomcatEmbeddedServletContainer(Tomcat, boolean) -> TomcatEmbeddedServletContainer.initialize
2017-07-09 22:16:36.776 INFO 26314 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat initialized with port(s): 8080 (http)
## TomcatEmbeddedServletContainer.initialize
## -> Tomcat.start -> LifecycleBase.start -> StandardServer.startInternal
## -> LifecycleBase.start -> StandardService.startInternal
2017-07-09 22:16:36.796 INFO 26314 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
## StandardService.startInternal
## -> LifecycleBase.start -> StandardEngine.startInternal
2017-07-09 22:16:36.797 INFO 26314 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet Engine: Apache Tomcat/8.5.15
## Thread[localhost-startStop-1,5,main].run -> ThreadPoolExecutor.Worker.run -> ThreadPoolExecutor.runWorker -> FutureTask.run
## -> ContainerBase.StartChild.call -> LifecycleBase.start -> StandardContext.startInternal
## -> TomcatStarter.onStartup -> EmbeddedWebApplicationContext.getSelfInitializer()$ServletContextInitializer.onStartup
## -> EmbeddedWebApplicationContext.selfInitialize -> EmbeddedWebApplicationContext.prepareEmbeddedWebApplicationContext
2017-07-09 22:16:36.928 INFO 26314 --- [ost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
## EmbeddedWebApplicationContext.prepareEmbeddedWebApplicationContext
2017-07-09 22:16:36.928 INFO 26314 --- [ost-startStop-1] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 2737 ms
## EmbeddedWebApplicationContext.selfInitialize
## -> ServletRegistrationBean.onStartup
2017-07-09 22:16:37.188 INFO 26314 --- [ost-startStop-1] o.s.b.w.servlet.ServletRegistrationBean : Mapping servlet: 'dispatcherServlet' to [/]
## EmbeddedWebApplicationContext.selfInitialize
## -> FilterRegistrationBean.onStartup -> AbstractFilterRegistrationBean.onStartup -> AbstractFilterRegistrationBean.configure
2017-07-09 22:16:37.195 INFO 26314 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'metricsFilter' to: [/*]
2017-07-09 22:16:37.195 INFO 26314 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'characterEncodingFilter' to: [/*]
2017-07-09 22:16:37.195 INFO 26314 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2017-07-09 22:16:37.196 INFO 26314 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'httpPutFormContentFilter' to: [/*]
2017-07-09 22:16:37.196 INFO 26314 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'requestContextFilter' to: [/*]
2017-07-09 22:16:37.196 INFO 26314 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'webRequestLoggingFilter' to: [/*]
2017-07-09 22:16:37.196 INFO 26314 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'applicationContextIdFilter' to: [/*]
## AbstractApplicationContext.refresh
## -> AbstractApplicationContext.finishBeanFactoryInitialization -> DefaultListableBeanFactory.preInstantiateSingletons
## -> AbstractBeanFactory.getBean(String) -> AbstractBeanFactory.doGetBean -> DefaultSingletonBeanRegistry.getSingleton(String, ObjectFactory<?>)
## -> AbstractBeanFactory$ObjectFactory.getObject -> AbstractAutowireCapableBeanFactory.createBean(String, RootBeanDefinition, Object[])
## -> AbstractAutowireCapableBeanFactory.doCreateBean -> AbstractAutowireCapableBeanFactory.initializeBean(String, Object, RootBeanDefinition)
## -> AbstractAutowireCapableBeanFactory.invokeInitMethods -> RequestMappingHandlerAdapter.afterPropertiesSet
## -> RequestMappingHandlerAdapter.initControllerAdviceCache
2017-07-09 22:16:37.673 INFO 26314 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@5e25a92e: startup date [Sun Jul 09 22:16:34 CST 2017]; root of context hierarchy
## AbstractAutowireCapableBeanFactory.invokeInitMethods
## -> RequestMappingHandlerMapping.afterPropertiesSet -> AbstractHandlerMethodMapping.afterPropertiesSet
## -> AbstractHandlerMethodMapping.initHandlerMethods -> AbstractHandlerMethodMapping.detectHandlerMethods
## -> AbstractHandlerMethodMapping.registerHandlerMethod -> AbstractHandlerMethodMapping.MappingRegistry.register
2017-07-09 22:16:37.763 INFO 26314 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/greeting],methods=[GET],produces=[application/json;charset=UTF-8]}" onto public spring.guides.hello.Greeting spring.guides.hello.GreetingController.greeting(java.lang.String)
2017-07-09 22:16:37.772 INFO 26314 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2017-07-09 22:16:37.773 INFO 26314 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
## AbstractAutowireCapableBeanFactory.initializeBean(String, Object, RootBeanDefinition)
## -> AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization
## -> ApplicationContextAwareProcessor.postProcessBeforeInitialization -> ApplicationContextAwareProcessor.invokeAwareInterfaces
## -> ApplicationObjectSupport.setApplicationContext -> WebApplicationObjectSupport.initApplicationContext
## -> ApplicationObjectSupport.initApplicationContext(ApplicationContext) -> SimpleUrlHandlerMapping.initApplicationContext
## -> SimpleUrlHandlerMapping.registerHandlers -> AbstractUrlHandlerMapping.registerHandler(String, Object)
2017-07-09 22:16:37.834 INFO 26314 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2017-07-09 22:16:37.834 INFO 26314 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2017-07-09 22:16:37.879 INFO 26314 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
## AbstractAutowireCapableBeanFactory.invokeInitMethods
## -> AbstractEndpointHandlerMapping.afterPropertiesSet -> AbstractHandlerMethodMapping.detectHandlerMethods
## -> AbstractEndpointHandlerMapping.registerHandlerMethod -> AbstractHandlerMethodMapping.registerHandlerMethod
## -> AbstractHandlerMethodMapping.MappingRegistry.register
2017-07-09 22:16:38.300 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/env/{name:.*}],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EnvironmentMvcEndpoint.value(java.lang.String)
2017-07-09 22:16:38.300 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/env || /env.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.301 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/info || /info.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.302 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/mappings || /mappings.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.303 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/auditevents || /auditevents.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public org.springframework.http.ResponseEntity<?> org.springframework.boot.actuate.endpoint.mvc.AuditEventsMvcEndpoint.findByPrincipalAndAfterAndType(java.lang.String,java.util.Date,java.lang.String)
2017-07-09 22:16:38.305 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/configprops || /configprops.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.305 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/autoconfig || /autoconfig.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.309 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/loggers/{name:.*}],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.LoggersMvcEndpoint.get(java.lang.String)
2017-07-09 22:16:38.310 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/loggers/{name:.*}],methods=[POST],consumes=[application/vnd.spring-boot.actuator.v1+json || application/json],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.LoggersMvcEndpoint.set(java.lang.String,java.util.Map<java.lang.String, java.lang.String>)
2017-07-09 22:16:38.310 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/loggers || /loggers.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.312 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/dump || /dump.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.313 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/heapdump || /heapdump.json],methods=[GET],produces=[application/octet-stream]}" onto public void org.springframework.boot.actuate.endpoint.mvc.HeapdumpMvcEndpoint.invoke(boolean,javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse) throws java.io.IOException,javax.servlet.ServletException
2017-07-09 22:16:38.314 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/trace || /trace.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.315 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/metrics/{name:.*}],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.MetricsMvcEndpoint.value(java.lang.String)
2017-07-09 22:16:38.316 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/metrics || /metrics.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
2017-07-09 22:16:38.317 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/health || /health.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.HealthMvcEndpoint.invoke(javax.servlet.http.HttpServletRequest,java.security.Principal)
2017-07-09 22:16:38.317 INFO 26314 --- [ main] o.s.b.a.e.mvc.EndpointHandlerMapping : Mapped "{[/beans || /beans.json],methods=[GET],produces=[application/vnd.spring-boot.actuator.v1+json || application/json]}" onto public java.lang.Object org.springframework.boot.actuate.endpoint.mvc.EndpointMvcAdapter.invoke()
## DefaultListableBeanFactory.preInstantiateSingletons
## -> MBeanExporter.afterSingletonsInstantiated
2017-07-09 22:16:38.441 INFO 26314 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
## AbstractApplicationContext.refresh
## -> EmbeddedWebApplicationContext.finishRefresh -> AbstractApplicationContext.finishRefresh
## -> DefaultLifecycleProcessor.onRefresh -> DefaultLifecycleProcessor.startBeans
## -> DefaultLifecycleProcessor.LifecycleGroup.start
2017-07-09 22:16:38.452 INFO 26314 --- [ main] o.s.c.support.DefaultLifecycleProcessor : Starting beans in phase 0
## EmbeddedWebApplicationContext.finishRefresh
## -> EmbeddedWebApplicationContext.startEmbeddedServletContainer -> TomcatEmbeddedServletContainer.start
2017-07-09 22:16:38.688 INFO 26314 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
# ================= 核心流程 =================
## SpringApplication.run(String...) -> StartupInfoLogger.logStarted -> StartupInfoLogger.getStartedMessage
2017-07-09 22:16:38.694 INFO 26314 --- [ main] spring.guides.hello.GreetingApplication : Started GreetingApplication in 5.483 seconds (JVM running for 6.291)
# ================= 首次请求 =================
## Thread[http-nio-8080-exec-1,5,main].run -> TaskThread.WrappingRunnable.run -> ThreadPoolExecutor.Worker.run -> ThreadPoolExecutor.runWorker
## -> SocketProcessorBase.run -> NioEndpoint.SocketProcessor.doRun -> AbstractProtocol.ConnectionHandler.process
## -> AbstractProcessorLight.process -> Http11Processor.service -> CoyoteAdapter.service -> AbstractAccessLogValve.invoke
## -> StandardEngineValve.invoke -> ErrorReportValve.invoke -> StandardHostValve.invoke -> AuthenticatorBase.invoke
## -> StandardContextValve.invoke -> StandardWrapperValve.invoke -> StandardWrapper.allocate
## -> StandardWrapper.initServlet -> GenericServlet.init(ServletConfig) -> HttpServletBean.init
## -> FrameworkServlet.initServletBean
2017-07-09 22:17:03.104 INFO 26314 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring FrameworkServlet 'dispatcherServlet'
## FrameworkServlet.initServletBean
2017-07-09 22:17:03.105 INFO 26314 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started
## FrameworkServlet.initServletBean
2017-07-09 22:17:03.126 INFO 26314 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 21 ms
# ================= 关闭应用 =================
## Thread[Thread-3,5,main].run -> AbstractApplicationContext.doClose
### Runtime.getRuntime().addShutdownHook(this.shutdownHook)
2017-07-09 22:17:53.994 INFO 26314 --- [ Thread-3] ationConfigEmbeddedWebApplicationContext : Closing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@5e25a92e: startup date [Sun Jul 09 22:16:34 CST 2017]; root of context hierarchy
## AbstractApplicationContext.doClose
## -> DefaultLifecycleProcessor.onClose -> DefaultLifecycleProcessor.stopBeans
## -> DefaultLifecycleProcessor.LifecycleGroup.stop
2017-07-09 22:17:53.996 INFO 26314 --- [ Thread-3] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 0
## AbstractApplicationContext.doClose
## -> AbstractApplicationContext.destroyBeans
## -> DefaultListableBeanFactory.destroySingletons -> DefaultSingletonBeanRegistry.destroySingletons
## -> DefaultListableBeanFactory.destroySingleton -> DefaultSingletonBeanRegistry.destroySingleton
## -> DefaultSingletonBeanRegistry.destroyBean -> DisposableBeanAdapter.destroy
## -> MBeanExporter.destroy
2017-07-09 22:17:54.001 INFO 26314 --- [ Thread-3] o.s.j.e.a.AnnotationMBeanExporter : Unregistering JMX-exposed beans on shutdown
Disconnected from the target VM, address: '127.0.0.1:54676', transport: 'socket'
Process finished with exit code 143 (interrupted by signal 15: SIGTERM)
祝玩得开心！ˇˍˇ
云舒，2017.8.31，杭州
