只需要一种选择：初学者阅读Spring Boot日志的文章

2 年 ago
韵, 科
8 minutes

首先

这篇文章是为了Spring Boot初学者而写的，仅涉及如何阅读Spring Boot日志。

环境

Java 8:
Java 8：

Spring Framework 5.3.21:
Spring框架 5.3.21：

Spring boot 2.7.1:
Spring Boot 2.7.1：

为什么想要阅读日志？

    • 何もしてないのにSpringが壊れた!

 

    • Springが吐いたエラーメッセージで検索してみたけどヒットしない！

 

    • ヒットはしたけど試してみても直らないしよくわからない！

 

    環境構築やり直し！！！となることがありました。

如果能够阅读日志和堆栈跟踪，我认为自己解决错误的概率会提高。

为什么无法阅读？

    • 読み方を知らない（読もうとしない）

 

    Spring bootが何をしているか知らない

对于第一个问题，我觉得是这样的，如果不去阅读的话，就无法阅读，并且也不会去查询阅读方法。

第二个原因是我不了解Spring Boot的功能。只要能对Spring Boot的功能有一定程度的了解，我就能差不多读懂日志。

在家里有一个能够做咖喱的家务机器人，突然它报错了，显示出以下的信息。“Error: 咖喱制作失败。土豆变得难以下咽。”
我们知道如何制作咖喱（或者应该知道），因此我们可以推测出各种原因，例如：“是不是土豆煮太烂了？”或“是不是过了保质期了？”并且在脑海中浮现出制作咖喱的场景。
第二天，家里有一台能够做埃索盖林乔巴斯的家务机器人，它显示了以下的错误信息。“Error: 无法制作埃索盖林乔巴斯。炒硬麦粒变得难以下咽。”
为什么硬麦粒会变得奇怪味道？
如果对于这道不熟悉的菜肴（如果我知道就不好意思了）既不了解制作过程也不了解专业词汇，那么就无法推测出为什么硬麦粒会变得奇怪味道。
Spring Boot也是这种情况，如果在应用程序启动之前无法了解它的操作步骤，或者遇到太多不熟悉的术语，就无法读取日志信息。
※埃索盖林乔巴斯是土耳其的一个菜肴，据说是为了体弱多病的新娘埃索（Ezo）的父亲而制作的。

这篇文章的目标是什么。

我的目标是向那些从未阅读过Spring日志的初学者传达Spring Boot日志不可怕的信息。
为此，我选择了一些适当的日志，并解释了我在初次阅读时不理解的一些内容。

做好准备

首先，我们准备一个用于查看日志的环境。可以使用任何方法，但我们决定使用Spring入门内容中的serving-web-content模块。

 

阅读日志时，仅仅读取日志中记录的字符并不能理解其中的内容，因此需要读取在日志中输出的代码部分。为此，我们准备了以下内容。

    • IDE（デバッグ用）

 

    • Spring公式Github

 

    ドキュメント（必要に応じて）

 

追踪日志附近的代码

当阅读日志前后的代码时，首先想到的方法是通过日志中包含的字符串进行搜索。然而，与普通的.java文件不同，Spring等外部项目通常是通过Gradle等工具进行jar包的形式提供的，因此无法在Eclipse等工具中进行搜索。（也许有可能可以，但并不确定）
但令人感激的是，Spring的代码在Github上是公开的。

最近，听说 GitHub 的搜索已经支持正则表达式了，但个人不太擅长搜索，所以最好能够在编辑器里打开。不过，我懒得克隆，所以经常使用以下的服务来解决。

 

image.png
image.png

我现在已经准备好了一边跟踪代码一边阅读日志的最低要求。
（说实话，这只是我想出来的一种权宜之计，可能还有更好的方法。如果有的话，希望能告诉我，谢谢。）

请尝试打开日志

在第一行中，它表示正在启动应用程序。
在第五行中，似乎正在初始化Web服务器（Tomcat）。
在第九行中，似乎正在初始化ServletWebServerApplicationContext。

顺便问一下，类似c.e.s.ServingWebContentApplication的c.e.s是什么意思呢？
另外，我不太了解ApplicationContext。

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.7.1)

// ↓ここから1行目
2022-12-16 12:29:03.744  INFO 27520 --- [  restartedMain] c.e.s.ServingWebContentApplication       : Starting ServingWebContentApplication using Java 1.8.0_332 on desktop_xxxx with PID 27520 (C:\Users\xxx\Documents\spring_start\gs-serving-web-content-complete\bin\main started by xxx in C:\Users\xxx\Documents\spring_start\gs-serving-web-content-complete) // ★
2022-12-16 12:29:03.745  INFO 27520 --- [  restartedMain] c.e.s.ServingWebContentApplication       : No active profile set, falling back to 1 default profile: "default"
2022-12-16 12:29:03.781  INFO 27520 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2022-12-16 12:29:03.781  INFO 27520 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2022-12-16 12:29:04.454  INFO 27520 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http) // ★
2022-12-16 12:29:04.465  INFO 27520 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-12-16 12:29:04.465  INFO 27520 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.64]
2022-12-16 12:29:04.514  INFO 27520 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-12-16 12:29:04.514  INFO 27520 --- [  restartedMain] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 733 ms // ★
2022-12-16 12:29:04.669  INFO 27520 --- [  restartedMain] o.s.b.a.w.s.WelcomePageHandlerMapping    : Adding welcome page: class path resource [static/index.html]
2022-12-16 12:29:04.774  INFO 27520 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2022-12-16 12:29:04.800  INFO 27520 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2022-12-16 12:29:04.808  INFO 27520 --- [  restartedMain] c.e.s.ServingWebContentApplication       : Started ServingWebContentApplication in 1.316 seconds (JVM running for 2.026)

日志格式

第一个问题的产生是因为我不了解日志的格式。

Spring Boot日志，从左到右

    1. 日期

 

    1. 日志级别

 

    1. 进程ID

 

    1. —（分隔符）

 

    1. 线程名

 

    1. 记录器名

 

    日志消息

在中文中表示为。例如，以下是一个例子：

2022-12-11 16:47:18.717 DEBUG 15276 --- [  restartedMain] o.s.boot.SpringApplication               : Loading source class com.example.servingwebcontent.ServingWebContentApplication
    1. 2022年12月11日16時47分18秒に、

 

    1. デバッグレベルのログが出力され、

 

    1. WebサーバーのプロセスIDは15276で、

 

    1. restartedMainスレッドで（devtoolsを使用するため）、「org.springframework.boot」の「SpringApplication.java」というロガー名で、

 

    「ServingWebContentApplication」がロードされています。

这句话的意思是。

 

WebApplicationContext是什么

这是一个提供网络应用程序配置的接口。其实质是一个DI容器（用于管理bean的基础设施）。在Spring Boot中，我们会将希望进行DI（依赖注入）的类交由它进行管理，并在需要时以下面的方式提取实例。

ApplicationContext context = ...;
HogeHoge hogeHoge = context.getBean(HogeHoge.class);
    DIコンテナの参考記事

 

让我们检查WebApplicationContext的初始化是做了什么。
日志输出的地方是在org.springframework.boot.web.servlet.context包的ServletWebServerAplicationContext类中进行的。

protected void prepareWebApplicationContext(ServletContext servletContext) {
    try {
        ...
        setServletContext(servletContext);
        if (logger.isInfoEnabled()) {
            long elapsedTime = System.currentTimeMillis() - getStartupDate();
            logger.info("Root WebApplicationContext: initialization completed in " + elapsedTime + " ms");
        }
    }
    catch (RuntimeException | Error ex) {
        ...
    }   
}

在WebApplicationContext的初始化完成日志之前，可以看到将servletContext设置为ApplicationContext。
ServletContext是JavaEE的一个接口，它定义了一组方法，用于使servlet与servlet容器进行通信。
我认为Spring将servlet注册到DI容器中，以便进行各种操作。

 

至少，如果追溯到源头，可以看出它是从createWebServer中调用的，所以它是准备启动Web服务器的一部分。

protected void onRefresh() {
		super.onRefresh();
		try {
			createWebServer(); //←ここ
		}
		catch (Throwable ex) {
			throw new ApplicationContextException("Unable to start web server", ex);
		}
	}

更改日志级别

顺便说一下，刚才显示的日志数量很少。
Spring Boot 的日志级别包括 ERROR、WARN、INFO、DEBUG 和 TRACE 这五种类型。
最简单的改变方法是修改 application.properties 文件。例如，如果想将根日志级别更改为DEBUG，可以按以下方式修改。

logging.level.root=DEBUG

 

查看 DEBUG 级别的日志

我改变了先前执行的应用程序的设置，尝试以DEBUG级别输出日志。
与刚才相比，日志明显变长。
虽然省略了一些内容，但是有很多单例Bean的创建共享实例的描述，让人感到困惑。
此外，在CONDITIONS EVALUATION REPORT下面写着Positive matches:和Negative matches:之类的内容，我不太理解。

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.7.1)

2022-12-11 16:47:18.716  INFO 15276 --- [  restartedMain] c.e.s.ServingWebContentApplication       : Starting ServingWebContentApplication using Java 1.8.0_332 on desktop_xxx with PID 15276 (C:\Users\xxx\Documents\spring_start\gs-serving-web-content-complete\bin\main started by xxx in C:\Users\xxx\Documents\spring_start\gs-serving-web-content-complete)
2022-12-11 16:47:18.716 DEBUG 15276 --- [  restartedMain] c.e.s.ServingWebContentApplication       : Running with Spring Boot v2.7.1, Spring v5.3.21
2022-12-11 16:47:18.717  INFO 15276 --- [  restartedMain] c.e.s.ServingWebContentApplication       : No active profile set, falling back to 1 default profile: "default"
2022-12-11 16:47:18.717 DEBUG 15276 --- [  restartedMain] o.s.boot.SpringApplication               : Loading source class com.example.servingwebcontent.ServingWebContentApplication
2022-12-11 16:47:18.739 DEBUG 15276 --- [  restartedMain] o.s.b.devtools.restart.ChangeableUrls    : Matching URLs for reloading : [file:/C:/Users/xxx/Documents/spring_start/gs-serving-web-content-complete/bin/main/]
2022-12-11 16:47:18.739 DEBUG 15276 --- [  restartedMain] o.s.b.d.settings.DevToolsSettings        : Included patterns for restart : []
2022-12-11 16:47:18.739 DEBUG 15276 --- [  restartedMain] o.s.b.d.settings.DevToolsSettings        : Excluded patterns for restart : [/spring-boot-actuator/(bin|build|out)/, /spring-boot-devtools/(bin|build|out)/, /spring-boot/(bin|build|out)/, /spring-boot-starter-[\w-]+/, /spring-boot-autoconfigure/(bin|build|out)/, /spring-boot-starter/(bin|build|out)/]
2022-12-11 16:47:18.739  INFO 15276 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2022-12-11 16:47:18.739  INFO 15276 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2022-12-11 16:47:18.740 DEBUG 15276 --- [  restartedMain] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@4bdc50a1
2022-12-11 16:47:18.750 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'
2022-12-11 16:47:18.757 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory' 
2022-12-11 16:47:18.760 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'propertySourcesPlaceholderConfigurer'
2022-12-11 16:47:18.760 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.boot.sql.init.dependency.DatabaseInitializationDependencyConfigurer$DependsOnDatabaseInitializationPostProcessor'
2022-12-11 16:47:18.763 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerProcessor'
2022-12-11 16:47:18.763 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'preserveErrorControllerTargetClassPostProcessor'
2022-12-11 16:47:18.768 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'forceAutoProxyCreatorToUseClassProxying'
2022-12-11 16:47:18.771 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerFactory'
2022-12-11 16:47:18.771 DEBUG 15276 --- [  restartedMain] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'org.springframework.context.annotation.internalAutowiredAnnotationProcessor'
...(省略)

============================
CONDITIONS EVALUATION REPORT
============================


Positive matches:
-----------------

   AopAutoConfiguration matched:
      - @ConditionalOnProperty (spring.aop.auto=true) matched (OnPropertyCondition)

   AopAutoConfiguration.ClassProxyingConfiguration matched:
      - @ConditionalOnMissingClass did not find unwanted class 'org.aspectj.weaver.Advice' (OnClassCondition)
      - @ConditionalOnProperty (spring.aop.proxy-target-class=true) matched (OnPropertyCondition)

...(省略)


Negative matches:
-----------------

   ActiveMQAutoConfiguration:
      Did not match:
         - @ConditionalOnClass did not find required class 'javax.jms.ConnectionFactory' (OnClassCondition)

   AopAutoConfiguration.AspectJAutoProxyingConfiguration:
      Did not match:
         - @ConditionalOnClass did not find required class 'org.aspectj.weaver.Advice' (OnClassCondition)

...(省略)


Exclusions:
-----------

    None


Unconditional classes:
----------------------

    org.springframework.boot.autoconfigure.context.ConfigurationPropertiesAutoConfiguration

    org.springframework.boot.autoconfigure.context.LifecycleAutoConfiguration

...(省略)


2022-12-11 16:47:19.432  INFO 15276 --- [  restartedMain] c.e.s.ServingWebContentApplication       : Started ServingWebContentApplication in 0.887 seconds (JVM running for 1.294)
2022-12-11 16:47:19.432 DEBUG 15276 --- [  restartedMain] o.s.b.a.ApplicationAvailabilityBean      : Application availability state LivenessState changed to CORRECT
2022-12-11 16:47:19.433 DEBUG 15276 --- [  restartedMain] o.s.boot.devtools.restart.Restarter      : Creating new Restarter for thread Thread[main,5,main]
2022-12-11 16:47:19.433 DEBUG 15276 --- [  restartedMain] o.s.boot.devtools.restart.Restarter      : Immediately restarting application
2022-12-11 16:47:19.433 DEBUG 15276 --- [  restartedMain] o.s.boot.devtools.restart.Restarter      : Starting application com.example.servingwebcontent.ServingWebContentApplication with URLs [file:/C:/Users/xxx/Documents/spring_start/gs-serving-web-content-complete/bin/main/]
2022-12-11 16:47:19.433 DEBUG 15276 --- [  restartedMain] o.s.b.a.ApplicationAvailabilityBean      : Application availability state ReadinessState changed to ACCEPTING_TRAFFIC
2022-12-11 16:47:19.654 DEBUG 15276 --- [on(2)-127.0.0.1] sun.rmi.transport.tcp                    : RMI TCP Connection(2)-127.0.0.1: (port 63303) op = 82
2022-12-11 16:47:19.656 DEBUG 15276 --- [on(2)-127.0.0.1] sun.rmi.transport.tcp                    : RMI TCP Connection(2)-127.0.0.1: (port 63303) op = 80
2022-12-11 16:47:19.657 DEBUG 15276 --- [on(2)-127.0.0.1] sun.rmi.loader                           : RMI TCP Connection(2)-127.0.0.1: name = "javax.management.ObjectName", codebase = ""

关于AutoConfiguratin

如果掌握了AutoConfiguration，大部分问题都可以解决。创建共享实例的意思是，我已经创建了实例，但是AutoConfiguration是Spring Boot自动创建实例的功能。关于AutoConfiguration，以下文章很容易理解。

在包含main方法的类上添加@SpringBootApplication注解，将会自动选择进行自动配置的类。

 

因为看了上述文章，你就可以理解这些机制，所以我将省略解释的部分。

在类路径上的/META-INF/spring.factories中获取要导入的配置类，并且以下的配置类将被作为导入目标。

经过查看仓库文件，我们发现在2022年2月的合并中，factory和Configuration类的记录文件已经分开，现在Configuration类的记录会被写入到META-INF/spring-autoconfigure-metadata.properties中。（截至2022年12月）

 

跟以前一样，我们还会检查日志记录的前后处理。
日志记录的部分在DefaultSingletonBeanRegistry.java文件的getSingleton方法中。
它所做的是很简单的，检查传入的beanName参数对应的bean是否已经被创建，如果没有，则进行创建。

public Object getSingleton(String beanName, ObjectFactory<?> singletonFactory) {
		Assert.notNull(beanName, "Bean name must not be null");
		synchronized (this.singletonObjects) {
			Object singletonObject = this.singletonObjects.get(beanName); // 既に作成済でないかチェック
			if (singletonObject == null) {
				...
				if (logger.isDebugEnabled()) {
					logger.debug("Creating shared instance of singleton bean '" + beanName + "'");
				}
				...
				try {
					singletonObject = singletonFactory.getObject(); // 作成
					newSingleton = true;
				}
				catch (IllegalStateException ex) {
                    ...
				}
				if (newSingleton) {
					addSingleton(beanName, singletonObject);
				}
			}
			return singletonObject; //作ったものを返却
		}
	}

关于条件评估报告

最后，说到”CONDITIONS EVALUATION REPORT”，它也与”AutoConfiguration”相关。
顺便提一下，之前我说过配置类在”META-INF/spring-autoconfigure-metadata.properties”中进行了配置，但我没有看过具体内容。我们来看一下。

org.springframework.boot.autoconfigure.admin.SpringApplicationAdminJmxAutoConfiguration
org.springframework.boot.autoconfigure.aop.AopAutoConfiguration
org.springframework.boot.autoconfigure.amqp.RabbitAutoConfiguration
org.springframework.boot.autoconfigure.batch.BatchAutoConfiguration
...

顺便一提，刚才的日志里，”Positive matches”的最上面有以下描述。

   AopAutoConfiguration matched:
      - @ConditionalOnProperty (spring.aop.auto=true) matched (OnPropertyCondition)

两个地方都出现了AopAutoConfiguration，是吧。CONDITIONS EVALUATION REPORT的内容似乎与AutoConfiguration有关。
我们来看看AopAutoConfiguration.java。

@AutoConfiguration
@ConditionalOnProperty(prefix = "spring.aop", name = "auto", havingValue = "true", matchIfMissing = true)
public class AopAutoConfiguration {
    ...
}

@ConditionalOnProperty 引起我的注意。这是Conditional注解中的一个，表示只在特定条件下才会进行Bean定义。

 

实际上，这个@ConditionalOnProperty与之前的条件评估报告相关。
条件评估报告是对有条件的配置进行何种判断的结果。

在中国语境下有各种类型的条件注释，但是对于@ConditionalOnProperty而言，它是当在application.properties或其他属性文件或系统属性中指定的注释存在时才会执行的。
换句话说，前面的日志中出现AopAutoConfiguration的Positive Match表示它满足了这个条件。

如果您尝试在application.properties中进行以下配置并重新运行，将会将Positive Match更改为Negative Match。

spring.aop.auto=false

Negative matches:
-----------------

   ActiveMQAutoConfiguration:
      Did not match:
         - @ConditionalOnClass did not find required class 'javax.jms.ConnectionFactory' (OnClassCondition)

接下来，下面的输出表示在Exclusions中，这些是开发者故意禁用的AutoConfiguration类。
让我们试试禁用AopAutoConfiguration。
要做到这一点，需要在main方法的类上的SpringBootApplication注解中指定exclude参数。

@SpringBootApplication(exclude = { AopAutoConfiguration.class })
public class ServingWebContentApplication {

    public static void main(String[] args) {
        SpringApplication.run(ServingWebContentApplication.class, args);
    }

}

当再次执行时，AopAutoConfiguration将在Exclusions部分中输出。

Exclusions:
-----------

    org.springframework.boot.autoconfigure.aop.AopAutoConfiguration

最后的非条件类是在条件评估报告中评价的对象，但是没有条件注释的类。
顺带提一下，这些日志输出是在org.springframework.boot.autoconfigure.logging文件夹的ContitionalEvaluationReportMessage.java中进行的。

// PositiveMatchesをログ出力している部分
private void logPositiveMatches(StringBuilder message, Map<String, ConditionAndOutcomes> shortOutcomes) {
		message.append(String.format("Positive matches:%n"));
		message.append(String.format("-----------------%n"));
		List<Entry<String, ConditionAndOutcomes>> matched = shortOutcomes.entrySet().stream()
				.filter((entry) -> entry.getValue().isFullMatch()).toList();
		if (matched.isEmpty()) {
			message.append(String.format("%n    None%n"));
		}
		else {
			matched.forEach((entry) -> addMatchLogMessage(message, entry.getKey(), entry.getValue()));
		}
		message.append(String.format("%n%n"));
	}

 

总结

我读了一下Spring Boot的日志。
虽然非常简化，可能会被严厉批评，但我发现当Spring Boot应用程序运行时，它会启动Web服务器，生成大量Bean并将它们注入到DI容器中。
仅仅了解以上内容可能会使你对Spring Boot的日志有一点耐心吧？我认为，即使启动失败，只要去”查找不懂的单词”或者”阅读代码”，你也能够读懂日志，希望能够传达出这个意思。

✖
广告
将在 10 秒后关闭
bannerAds