初学SpringBoot之二

Posted 2020-09-24 神跳跳

原文教程链接在此http://blog.csdn.net/lxhjh/article/details/51752419。

使用了org.slf4j.Logger和org.slf4j.LoggerFactory

贴三句代码：

protected static Logger logger=LoggerFactory.getLogger(HelloController.class);

logger.debug("访问hello");

logger.debug("访问helloName,Name={}",name);

-----------------------------------------------------------------------------------

记录问题：

按教程正常操作后，日志文件一直没有找到。

解决过程：

1.阅读console输出。

   1)发现Spring这里先加载了resource目录下的logback.xml配置文件，然后才是后续的SpringBoot一系列启动执行过程，这里可能涉及Spring的加载机制，暂且放下，留作以后发现。

   2)发现这里输出的文字都是乱码，后来在logback.xml中修改了对应的<charset>为utf-8，重启后输出正常。这里猜测eclipse控制台默认解码为utf-8，暂且不做研究。这里同样发现了昨天的问题，就是SpringBoot启动后，代码的修改都不会生效，很是奇怪。

   3)还有一个发现，console的输出格式，刚好是 %d %p (%file:%line\)- %m%n  。

2.阅读logback.xml。

   配置了两种appender，分别对应<root><logger>，level分别为info、debug。其中配置对应关系，尚需详查。

3.刷新项目目录。

   解决。。。。。。坑啊有点，而且打开日志文件，再次从前端访问，日志文件内容并无变化，重启eclipse后打开日志文件，发现有了。。。

   这里的刷新机制真心有点奇怪。。。

------------------------------------------

粗略记录三个问题，以待查询：

1.SpringBoot的加载机制，如加入resource下的文件后。

2.SpringBoot刷新机制，如启动后修改代码不生效。

3.日志框架，如log4j,slf4j。

------------------------------------------------------------------------------------------

将console和log/base.log的内容记录在此：

console：

10:55:03,210 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
10:55:03,210 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
10:55:03,210 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Z:/ChromeDownloads/spring-boot-sample-helloworld/spring-boot-sample-helloworld/target/classes/logback.xml]
10:55:03,366 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
10:55:03,366 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
10:55:03,397 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
10:55:03,413 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:55:03,569 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
10:55:03,585 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [baselog]
10:55:03,631 |-INFO in [email protected] - No compression will be used
10:55:03,631 |-INFO in [email protected] - Will use the pattern log/base.log.%d.%i for the active file
10:55:03,631 |-INFO in [email protected] - The date pattern is ‘yyyy-MM-dd‘ from file name pattern ‘log/base.log.%d.%i‘.
10:55:03,631 |-INFO in [email protected] - Roll-over at midnight.
10:55:03,663 |-INFO in [email protected] - Setting initial period to Sun Jun 25 10:25:50 CST 2017
10:55:03,663 |-WARN in [email protected] - SizeAndTimeBasedFNATP is deprecated. Use SizeAndTimeBasedRollingPolicy instead
10:55:03,663 |-WARN in [email protected] - For more information see http://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedRollingPolicy
10:55:03,678 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:55:03,678 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[baselog] - Active log file name: log/base.log
10:55:03,678 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[baselog] - File property is set to [log/base.log]
10:55:03,694 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
10:55:03,694 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
10:55:03,694 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.example] to DEBUG
10:55:03,694 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [baselog] to Logger[com.example]
10:55:03,694 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
10:55:03,694 |-INFO in [email protected] - Registering current configuration as safe fallback point

. ____ _ __ _ _
/\\ / ___‘_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | ‘_ | ‘_| | ‘_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
‘ |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v1.5.4.RELEASE)

2017-06-25 10:55:05,441 INFO (StartupInfoLogger.java:48)- Starting SpringBootSampleHelloworldApplication on OQBNBM1JE2S28LI with PID 6404 (Z:\ChromeDownloads\spring-boot-sample-helloworld\spring-boot-sample-helloworld\target\classes started by Administrator in Z:\ChromeDownloads\spring-boot-sample-helloworld\spring-boot-sample-helloworld)
2017-06-25 10:55:05,456 DEBUG (StartupInfoLogger.java:51)- Running with Spring Boot v1.5.4.RELEASE, Spring v4.3.9.RELEASE
2017-06-25 10:55:05,456 INFO (SpringApplication.java:593)- No active profile set, falling back to default profiles: default
2017-06-25 10:55:05,628 INFO (AbstractApplicationContext.java:583)- Refreshing org.springframework.boot[email protected]ca263c2: startup date [Sun Jun 25 10:55:05 CST 2017]; root of context hierarchy
2017-06-25 10:55:06,409 INFO (Version.java:30)- HV000001: Hibernate Validator 5.3.5.Final
2017-06-25 10:55:10,660 INFO (TomcatEmbeddedServletContainer.java:89)- Tomcat initialized with port(s): 8080 (http)
2017-06-25 10:55:10,697 INFO (DirectJDKLog.java:179)- Starting service [Tomcat]
2017-06-25 10:55:10,697 INFO (DirectJDKLog.java:179)- Starting Servlet Engine: Apache Tomcat/8.5.15
2017-06-25 10:55:11,166 INFO (DirectJDKLog.java:179)- Initializing Spring embedded WebApplicationContext
2017-06-25 10:55:11,166 INFO (EmbeddedWebApplicationContext.java:276)- Root WebApplicationContext: initialization completed in 5538 ms
2017-06-25 10:55:11,838 INFO (ServletRegistrationBean.java:190)- Mapping servlet: ‘dispatcherServlet‘ to [/]
2017-06-25 10:55:11,856 INFO (AbstractFilterRegistrationBean.java:258)- Mapping filter: ‘characterEncodingFilter‘ to: [/*]
2017-06-25 10:55:11,856 INFO (AbstractFilterRegistrationBean.java:258)- Mapping filter: ‘hiddenHttpMethodFilter‘ to: [/*]
2017-06-25 10:55:11,856 INFO (AbstractFilterRegistrationBean.java:258)- Mapping filter: ‘httpPutFormContentFilter‘ to: [/*]
2017-06-25 10:55:11,856 INFO (AbstractFilterRegistrationBean.java:258)- Mapping filter: ‘requestContextFilter‘ to: [/*]
2017-06-25 10:55:12,825 INFO (RequestMappingHandlerAdapter.java:534)- Looking for @ControllerAdvice: org.springframework.boot[email protected]ca263c2: startup date [Sun Jun 25 10:55:05 CST 2017]; root of context hierarchy
2017-06-25 10:55:13,066 INFO (AbstractHandlerMethodMapping.java:543)- Mapped "{[/hello/]}" onto public java.lang.String com.example.HelloController.helloName2()
2017-06-25 10:55:13,066 INFO (AbstractHandlerMethodMapping.java:543)- Mapped "{[/hello/{name}]}" onto public java.lang.String com.example.HelloController.helloName(java.lang.String)
2017-06-25 10:55:13,066 INFO (AbstractHandlerMethodMapping.java:543)- Mapped "{[/]}" onto public java.lang.String com.example.HelloController.helloWorld()
2017-06-25 10:55:13,066 INFO (AbstractHandlerMethodMapping.java:543)- Mapped "{[/shello/]}" onto public java.lang.String com.example.locationTest.HellooController.helloName2()
2017-06-25 10:55:13,082 INFO (AbstractHandlerMethodMapping.java:543)- Mapped "{[/shello/{name}]}" onto public java.lang.String com.example.locationTest.HellooController.helloName(java.lang.String)
2017-06-25 10:55:13,082 INFO (AbstractHandlerMethodMapping.java:543)- Mapped "{[/s]}" onto public java.lang.String com.example.locationTest.HellooController.helloWorld()
2017-06-25 10:55:13,082 INFO (AbstractHandlerMethodMapping.java:543)- 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-06-25 10:55:13,098 INFO (AbstractHandlerMethodMapping.java:543)- 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)
2017-06-25 10:55:13,176 INFO (AbstractUrlHandlerMapping.java:362)- Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2017-06-25 10:55:13,176 INFO (AbstractUrlHandlerMapping.java:362)- Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2017-06-25 10:55:13,285 INFO (AbstractUrlHandlerMapping.java:362)- Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2017-06-25 10:55:13,645 INFO (MBeanExporter.java:431)- Registering beans for JMX exposure on startup
2017-06-25 10:55:13,691 INFO (DirectJDKLog.java:179)- Initializing ProtocolHandler ["http-nio-8080"]
2017-06-25 10:55:13,723 INFO (DirectJDKLog.java:179)- Starting ProtocolHandler ["http-nio-8080"]
2017-06-25 10:55:13,754 INFO (DirectJDKLog.java:179)- Using a shared selector for servlet write/read
2017-06-25 10:55:13,832 INFO (TomcatEmbeddedServletContainer.java:201)- Tomcat started on port(s): 8080 (http)
2017-06-25 10:55:13,848 INFO (StartupInfoLogger.java:57)- Started SpringBootSampleHelloworldApplication in 9.679 seconds (JVM running for 11.227)
2017-06-25 10:55:14,406 INFO (DirectJDKLog.java:179)- Initializing Spring FrameworkServlet ‘dispatcherServlet‘
2017-06-25 10:55:14,406 INFO (FrameworkServlet.java:489)- FrameworkServlet ‘dispatcherServlet‘: initialization started
2017-06-25 10:55:14,453 INFO (FrameworkServlet.java:508)- FrameworkServlet ‘dispatcherServlet‘: initialization completed in 47 ms
2017-06-25 10:55:14,609 DEBUG (HelloController.java:22)- 访问helloName,Name=aaaaaallllllllllll

 

log/base.log:

2017-06-25 09:16:20,168 INFO (StartupInfoLogger.java:48)- Starting SpringBootSampleHelloworldApplication on OQBNBM1JE2S28LI with PID 3108 (Z:\ChromeDownloads\spring-boot-sample-helloworld\spring-boot-sample-helloworld\target\classes started by Administrator in Z:\ChromeDownloads\spring-boot-sample-helloworld\spring-boot-sample-helloworld)
2017-06-25 09:16:20,168 DEBUG (StartupInfoLogger.java:51)- Running with Spring Boot v1.5.4.RELEASE, Spring v4.3.9.RELEASE
2017-06-25 09:16:20,168 INFO (SpringApplication.java:593)- No active profile set, falling back to default profiles: default
2017-06-25 09:16:28,812 INFO (StartupInfoLogger.java:57)- Started SpringBootSampleHelloworldApplication in 9.891 seconds (JVM running for 11.537)
2017-06-25 09:18:43,363 DEBUG (HelloController.java:16)- 访问hello
2017-06-25 09:50:38,944 DEBUG (HelloController.java:16)- 访问hello
2017-06-25 09:50:57,783 DEBUG (HelloController.java:22)- 访问helloName,Name=ok
2017-06-25 09:52:05,423 DEBUG (HelloController.java:22)- 访问helloName,Name=ok
2017-06-25 09:53:18,761 INFO (StartupInfoLogger.java:48)- Starting SpringBootSampleHelloworldApplication on OQBNBM1JE2S28LI with PID 3572 (Z:\ChromeDownloads\spring-boot-sample-helloworld\spring-boot-sample-helloworld\target\classes started by Administrator in Z:\ChromeDownloads\spring-boot-sample-helloworld\spring-boot-sample-helloworld)
2017-06-25 09:53:18,778 DEBUG (StartupInfoLogger.java:51)- Running with Spring Boot v1.5.4.RELEASE, Spring v4.3.9.RELEASE
2017-06-25 09:53:18,780 INFO (SpringApplication.java:593)- No active profile set, falling back to default profiles: default
2017-06-25 09:53:26,948 INFO (StartupInfoLogger.java:57)- Started SpringBootSampleHelloworldApplication in 10.671 seconds (JVM running for 14.205)
2017-06-25 09:54:43,480 DEBUG (HelloController.java:22)- 访问helloName,Name=ok
2017-06-25 10:09:09,681 DEBUG (HelloController.java:22)- 访问helloName,Name=aaaaaa
2017-06-25 10:25:48,719 DEBUG (HelloController.java:22)- 访问helloName,Name=aaaaaallllllllllll
2017-06-25 10:55:05,441 INFO (StartupInfoLogger.java:48)- Starting SpringBootSampleHelloworldApplication on OQBNBM1JE2S28LI with PID 6404 (Z:\ChromeDownloads\spring-boot-sample-helloworld\spring-boot-sample-helloworld\target\classes started by Administrator in Z:\ChromeDownloads\spring-boot-sample-helloworld\spring-boot-sample-helloworld)
2017-06-25 10:55:05,456 DEBUG (StartupInfoLogger.java:51)- Running with Spring Boot v1.5.4.RELEASE, Spring v4.3.9.RELEASE
2017-06-25 10:55:05,456 INFO (SpringApplication.java:593)- No active profile set, falling back to default profiles: default
2017-06-25 10:55:13,848 INFO (StartupInfoLogger.java:57)- Started SpringBootSampleHelloworldApplication in 9.679 seconds (JVM running for 11.227)
2017-06-25 10:55:14,609 DEBUG (HelloController.java:22)- 访问helloName,Name=aaaaaallllllllllll