C:\apache-tomcat-8.0.36\bin\catalina.bat run
[2018-05-23 02:30:31,657] Artifact demo-springmvc:war exploded: Waiting for server connection to start artifact deployment...
Using CATALINA_BASE: "C:\Users\TQ\.IntelliJIdea2017.2\system\tomcat\Unnamed_demo-springmvc"
Using CATALINA_HOME: "C:\apache-tomcat-8.0.36"
Using CATALINA_TMPDIR: "C:\apache-tomcat-8.0.36\temp"
Using JRE_HOME: "C:\Program Files\Java\jdk1.8.0_25"
Using CLASSPATH: "C:\apache-tomcat-8.0.36\bin\bootstrap.jar;C:\apache-tomcat-8.0.36\bin\tomcat-juli.jar"
23-May-2018 14:30:32.688 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version: Apache Tomcat/8.0.36
23-May-2018 14:30:32.689 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Jun 9 2016 13:55:50 UTC
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number: 8.0.36.0
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: Windows 8.1
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 6.3
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: C:\Program Files\Java\jdk1.8.0_25\jre
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 1.8.0_25-b18
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: Oracle Corporation
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: C:\Users\TQ\.IntelliJIdea2017.2\system\tomcat\Unnamed_demo-springmvc
23-May-2018 14:30:32.690 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: C:\apache-tomcat-8.0.36
23-May-2018 14:30:32.691 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote=
23-May-2018 14:30:32.691 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.port=1099
23-May-2018 14:30:32.691 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.ssl=false
23-May-2018 14:30:32.691 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.authenticate=false
23-May-2018 14:30:32.692 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.rmi.server.hostname=127.0.0.1
23-May-2018 14:30:32.692 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
23-May-2018 14:30:32.693 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=C:\Users\TQ\.IntelliJIdea2017.2\system\tomcat\Unnamed_demo-springmvc\conf\logging.properties
23-May-2018 14:30:32.693 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
23-May-2018 14:30:32.693 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.endorsed.dirs=C:\apache-tomcat-8.0.36\endorsed
23-May-2018 14:30:32.693 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=C:\Users\TQ\.IntelliJIdea2017.2\system\tomcat\Unnamed_demo-springmvc
23-May-2018 14:30:32.693 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=C:\apache-tomcat-8.0.36
23-May-2018 14:30:32.693 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=C:\apache-tomcat-8.0.36\temp
23-May-2018 14:30:32.693 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded APR based Apache Tomcat Native library 1.2.7 using APR version 1.5.2.
23-May-2018 14:30:32.693 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
23-May-2018 14:30:33.477 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized (OpenSSL 1.0.2h 3 May 2016)
23-May-2018 14:30:33.610 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-apr-8080"]
23-May-2018 14:30:33.622 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-apr-8009"]
23-May-2018 14:30:33.623 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 1325 ms
23-May-2018 14:30:33.662 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service Catalina
23-May-2018 14:30:33.662 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.0.36
23-May-2018 14:30:33.688 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-apr-8080"]
23-May-2018 14:30:33.709 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-apr-8009"]
23-May-2018 14:30:33.711 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 88 ms
Connected to server
[2018-05-23 02:30:33,743] Artifact demo-springmvc:war exploded: Artifact is being deployed, please wait...
23-May-2018 14:30:35.178 INFO [RMI TCP Connection(3)-127.0.0.1] org.apache.jasper.servlet.TldScanner.scanJars 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.
23-May-2018 14:30:35.246 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.context.ContextLoader.initWebApplicationContext Root WebApplicationContext: initialization started
23-May-2018 14:30:35.336 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.context.support.XmlWebApplicationContext.prepareRefresh Refreshing Root WebApplicationContext: startup date [Wed May 23 14:30:35 CST 2018]; root of context hierarchy
23-May-2018 14:30:35.425 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions Loading XML bean definitions from ServletContext resource [/WEB-INF/applicationContext.xml]
23-May-2018 14:30:35.589 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.context.ContextLoader.initWebApplicationContext Root WebApplicationContext: initialization completed in 343 ms
23-May-2018 14:30:35.723 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.DispatcherServlet.initServletBean FrameworkServlet 'dispatcher': initialization started
23-May-2018 14:30:35.729 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.context.support.XmlWebApplicationContext.prepareRefresh Refreshing WebApplicationContext for namespace 'dispatcher-servlet': startup date [Wed May 23 14:30:35 CST 2018]; parent: Root WebApplicationContext
23-May-2018 14:30:35.730 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions Loading XML bean definitions from ServletContext resource [/WEB-INF/dispatcher-servlet2.xml]
23-May-2018 14:30:36.548 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping.register Mapped "{[/user/get],methods=[GET],produces=[text/plain;charset=utf-8]}" onto public java.lang.String com.example.demo.controller.UserController.get(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
23-May-2018 14:30:36.664 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.initControllerAdviceCache Looking for @ControllerAdvice: WebApplicationContext for namespace 'dispatcher-servlet': startup date [Wed May 23 14:30:35 CST 2018]; parent: Root WebApplicationContext
23-May-2018 14:30:36.735 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.initControllerAdviceCache Looking for @ControllerAdvice: WebApplicationContext for namespace 'dispatcher-servlet': startup date [Wed May 23 14:30:35 CST 2018]; parent: Root WebApplicationContext
23-May-2018 14:30:36.947 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.DispatcherServlet.initServletBean FrameworkServlet 'dispatcher': initialization completed in 1224 ms
[2018-05-23 02:30:36,975] Artifact demo-springmvc:war exploded: Artifact is deployed successfully
[2018-05-23 02:30:36,975] Artifact demo-springmvc:war exploded: Deploy took 3,232 milliseconds
截取spring部分日志
23-May-2018 14:30:35.178 INFO [RMI TCP Connection(3)-127.0.0.1] org.apache.jasper.servlet.TldScanner.scanJars 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.
23-May-2018 14:30:35.246 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.context.ContextLoader.initWebApplicationContext Root WebApplicationContext: initialization started
23-May-2018 14:30:35.336 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.context.support.XmlWebApplicationContext.prepareRefresh Refreshing Root WebApplicationContext: startup date [Wed May 23 14:30:35 CST 2018]; root of context hierarchy
23-May-2018 14:30:35.425 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions Loading XML bean definitions from ServletContext resource [/WEB-INF/applicationContext.xml]
23-May-2018 14:30:35.589 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.context.ContextLoader.initWebApplicationContext Root WebApplicationContext: initialization completed in 343 ms
23-May-2018 14:30:35.723 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.DispatcherServlet.initServletBean FrameworkServlet 'dispatcher': initialization started
23-May-2018 14:30:35.729 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.context.support.XmlWebApplicationContext.prepareRefresh Refreshing WebApplicationContext for namespace 'dispatcher-servlet': startup date [Wed May 23 14:30:35 CST 2018]; parent: Root WebApplicationContext
23-May-2018 14:30:35.730 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions Loading XML bean definitions from ServletContext resource [/WEB-INF/dispatcher-servlet2.xml]
23-May-2018 14:30:36.548 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping.register Mapped "{[/user/get],methods=[GET],produces=[text/plain;charset=utf-8]}" onto public java.lang.String com.example.demo.controller.UserController.get(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
23-May-2018 14:30:36.664 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.initControllerAdviceCache Looking for @ControllerAdvice: WebApplicationContext for namespace 'dispatcher-servlet': startup date [Wed May 23 14:30:35 CST 2018]; parent: Root WebApplicationContext
23-May-2018 14:30:36.735 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.initControllerAdviceCache Looking for @ControllerAdvice: WebApplicationContext for namespace 'dispatcher-servlet': startup date [Wed May 23 14:30:35 CST 2018]; parent: Root WebApplicationContext
23-May-2018 14:30:36.947 INFO [RMI TCP Connection(3)-127.0.0.1] org.springframework.web.servlet.DispatcherServlet.initServletBean FrameworkServlet 'dispatcher': initialization completed in 1224 ms
从第2行开始到第12行为spring启动阶段log打出的所有info日志
定位其源码位置
public WebApplicationContext initWebApplicationContext(ServletContext servletContext) {
if (servletContext.getAttribute(WebApplicationContext.ROOT_WEB_APPLICATION_CONTEXT_ATTRIBUTE) != null) {
throw new IllegalStateException(
"Cannot initialize context because there is already a root application context present - " +
"check whether you have multiple ContextLoader* definitions in your web.xml!");
}
Log logger = LogFactory.getLog(ContextLoader.class);
servletContext.log("Initializing Spring root WebApplicationContext");
if (logger.isInfoEnabled()) {
logger.info("Root WebApplicationContext: initialization started");// 日志第2行
}
long startTime = System.currentTimeMillis();
try {
// Store context in local instance variable, to guarantee that
// it is available on ServletContext shutdown.
if (this.context == null) {
this.context = createWebApplicationContext(servletContext);
}
if (this.context instanceof ConfigurableWebApplicationContext) {
ConfigurableWebApplicationContext cwac = (ConfigurableWebApplicationContext) this.context;
if (!cwac.isActive()) {
// The context has not yet been refreshed -> provide services such as
// setting the parent context, setting the application context id, etc
if (cwac.getParent() == null) {
// The context instance was injected without an explicit parent ->
// determine parent for root web application context, if any.
ApplicationContext parent = loadParentContext(servletContext);
cwac.setParent(parent);
}
configureAndRefreshWebApplicationContext(cwac, servletContext);
}
}
servletContext.setAttribute(WebApplicationContext.ROOT_WEB_APPLICATION_CONTEXT_ATTRIBUTE, this.context);
ClassLoader ccl = Thread.currentThread().getContextClassLoader();
if (ccl == ContextLoader.class.getClassLoader()) {
currentContext = this.context;
}
else if (ccl != null) {
currentContextPerThread.put(ccl, this.context);
}
if (logger.isDebugEnabled()) {
logger.debug("Published root WebApplicationContext as ServletContext attribute with name [" +
WebApplicationContext.ROOT_WEB_APPLICATION_CONTEXT_ATTRIBUTE + "]");
}
if (logger.isInfoEnabled()) {
long elapsedTime = System.currentTimeMillis() - startTime;
logger.info("Root WebApplicationContext: initialization completed in " + elapsedTime + " ms");// 日志第5行
}
return this.context;
}
catch (RuntimeException ex) {
logger.error("Context initialization failed", ex);
servletContext.setAttribute(WebApplicationContext.ROOT_WEB_APPLICATION_CONTEXT_ATTRIBUTE, ex);
throw ex;
}
catch (Error err) {
logger.error("Context initialization failed", err);
servletContext.setAttribute(WebApplicationContext.ROOT_WEB_APPLICATION_CONTEXT_ATTRIBUTE, err);
throw err;
}
}
protected void configureAndRefreshWebApplicationContext(ConfigurableWebApplicationContext wac, ServletContext sc) {
if (ObjectUtils.identityToString(wac).equals(wac.getId())) {
// The application context id is still set to its original default value
// -> assign a more useful id based on available information
String idParam = sc.getInitParameter(CONTEXT_ID_PARAM);
if (idParam != null) {
wac.setId(idParam);
}
else {
// Generate default id...
wac.setId(ConfigurableWebApplicationContext.APPLICATION_CONTEXT_ID_PREFIX +
ObjectUtils.getDisplayString(sc.getContextPath()));
}
}
wac.setServletContext(sc);
String configLocationParam = sc.getInitParameter(CONFIG_LOCATION_PARAM);
if (configLocationParam != null) {
wac.setConfigLocation(configLocationParam);
}
// The wac environment's #initPropertySources will be called in any case when the context
// is refreshed; do it eagerly here to ensure servlet property sources are in place for
// use in any post-processing or initialization that occurs below prior to #refresh
ConfigurableEnvironment env = wac.getEnvironment();
if (env instanceof ConfigurableWebEnvironment) {
((ConfigurableWebEnvironment) env).initPropertySources(sc, null);
}
customizeContext(sc, wac);
wac.refresh();
}
@Override
public void refresh() throws BeansException, IllegalStateException {
synchronized (this.startupShutdownMonitor) {
// Prepare this context for refreshing.
prepareRefresh(); // Tell the subclass to refresh the internal bean factory.
ConfigurableListableBeanFactory beanFactory = obtainFreshBeanFactory(); // Prepare the bean factory for use in this context.
prepareBeanFactory(beanFactory); try {
// Allows post-processing of the bean factory in context subclasses.
postProcessBeanFactory(beanFactory); // Invoke factory processors registered as beans in the context.
invokeBeanFactoryPostProcessors(beanFactory); // Register bean processors that intercept bean creation.
registerBeanPostProcessors(beanFactory); // Initialize message source for this context.
initMessageSource(); // Initialize event multicaster for this context.
initApplicationEventMulticaster(); // Initialize other special beans in specific context subclasses.
onRefresh(); // Check for listener beans and register them.
registerListeners(); // Instantiate all remaining (non-lazy-init) singletons.
finishBeanFactoryInitialization(beanFactory); // Last step: publish corresponding event.
finishRefresh();
} catch (BeansException ex) {
if (logger.isWarnEnabled()) {
logger.warn("Exception encountered during context initialization - " +
"cancelling refresh attempt: " + ex);
} // Destroy already created singletons to avoid dangling resources.
destroyBeans(); // Reset 'active' flag.
cancelRefresh(ex); // Propagate exception to caller.
throw ex;
} finally {
// Reset common introspection caches in Spring's core, since we
// might not ever need metadata for singleton beans anymore...
resetCommonCaches();
}
}
} /**
* Prepare this context for refreshing, setting its startup date and
* active flag as well as performing any initialization of property sources.
*/
protected void prepareRefresh() {
this.startupDate = System.currentTimeMillis();
this.closed.set(false);
this.active.set(true); if (logger.isInfoEnabled()) {
logger.info("Refreshing " + this);// 日志第3行
} // Initialize any placeholder property sources in the context environment
initPropertySources(); // Validate that all properties marked as required are resolvable
// see ConfigurablePropertyResolver#setRequiredProperties
getEnvironment().validateRequiredProperties(); // Allow for the collection of early ApplicationEvents,
// to be published once the multicaster is available...
this.earlyApplicationEvents = new LinkedHashSet<ApplicationEvent>();
}
/**
* Load bean definitions from the specified XML file.
* @param encodedResource the resource descriptor for the XML file,
* allowing to specify an encoding to use for parsing the file
* @return the number of bean definitions found
* @throws BeanDefinitionStoreException in case of loading or parsing errors
*/
public int loadBeanDefinitions(EncodedResource encodedResource) throws BeanDefinitionStoreException {
Assert.notNull(encodedResource, "EncodedResource must not be null");
if (logger.isInfoEnabled()) {
logger.info("Loading XML bean definitions from " + encodedResource.getResource());// 日志第4行
} Set<EncodedResource> currentResources = this.resourcesCurrentlyBeingLoaded.get();
if (currentResources == null) {
currentResources = new HashSet<EncodedResource>(4);
this.resourcesCurrentlyBeingLoaded.set(currentResources);
}
if (!currentResources.add(encodedResource)) {
throw new BeanDefinitionStoreException(
"Detected cyclic loading of " + encodedResource + " - check your import definitions!");
}
try {
InputStream inputStream = encodedResource.getResource().getInputStream();
try {
InputSource inputSource = new InputSource(inputStream);
if (encodedResource.getEncoding() != null) {
inputSource.setEncoding(encodedResource.getEncoding());
}
return doLoadBeanDefinitions(inputSource, encodedResource.getResource());
}
finally {
inputStream.close();
}
}
catch (IOException ex) {
throw new BeanDefinitionStoreException(
"IOException parsing XML document from " + encodedResource.getResource(), ex);
}
finally {
currentResources.remove(encodedResource);
if (currentResources.isEmpty()) {
this.resourcesCurrentlyBeingLoaded.remove();
}
}
}
从日志反分析spring web的启动过程
之后是loadBean
ps：idea返回至上次浏览的位置快捷键Ctrl+Shift+Left/Right