美文网首页Spring BootSpring boot
Spring Boot和Tomcat的启动日志源码调用剖析

Spring Boot和Tomcat的启动日志源码调用剖析

作者: 简放视野 | 来源:发表于2017-08-31 20:13 被阅读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,杭州

    相关文章

      网友评论

        本文标题:Spring Boot和Tomcat的启动日志源码调用剖析

        本文链接:https://www.haomeiwen.com/subject/zmjcjxtx.html