为什么 Spring 不跟我说话？（或者：如何正确配置 Spring 日志记录？）

Question

我的实际问题是 Spring Security 和为身份验证服务器配置 OAuth2，但是为了在那里跟踪我的问题，我希望 Spring 告诉我当请求到达端点时实际发生了什么。我正在使用 Spring Boot 2.0.0-SNAPSHOT 和日志记录启动器spring-boot-starter-log4j2，实际上它似乎工作得很好。我的 log4j2 配置是：

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE Configuration>
<Configuration status="WARN">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%-5level%d{MMM dd, yyyy HH:mm:ss.SSS} [%t] %X %logger{36}%n  %msg%n"/>
    </Console>
  <File name="File" fileName="logs/application.log">
    <PatternLayout pattern="%-5level%d{MMM dd, yyyy HH:mm:ss.SSS} [%t] %X %logger{36} %msg%n"/>
  </File>
  </Appenders>
  <Loggers>    
    <Root level="debug">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </Root>
    <logger name="org.springframework" level="debug" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </logger>
    <logger name="org.springframework.security" level="debug" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </logger>
    <logger name="org.hibernate" level="info" additivity="false">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="File"/>
    </logger>
  </Loggers>
</Configuration>

在启动应用程序（嵌入式 Tomcat）时，我可以看到实际上使用了配置，并且 Spring 在此过程中记录了很多东西：

...
INFO Feb 02, 2018 11:31:00.295 [restartedMain] {} org.hibernate.type.BasicTypeRegistry
  HHH000270: Type registration [java.util.UUID] overrides previous : org.hibernate.type.UUIDBinaryType@41229bd4
INFO Feb 02, 2018 11:31:00.345 [restartedMain] {} org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean
  Initialized JPA EntityManagerFactory for persistence unit 'default'
DEBUG Feb 02, 2018 11:31:00.440 [restartedMain] {} org.springframework.data.jpa.repository.query.JpaQueryFactory
  Looking up query for method findByEmail
...

但是当我向应用程序发送请求以获取接收 4xx 错误的 Oauth2 访问令牌时，我希望 Spring 告诉我它做了什么，以便我可以找到我的配置错误。但它不会记录任何内容。我看到了 Hiberante 的东西和我自己的日志记录，但 Spring 保持沉默。由于 TRACE 配置，我预计会收到很多消息。

任何人都可以想象，我做错了什么？还是 Spring 根本不爱说话？

更新 02/08/2018：
看来我的问题与 Spring Security 有关。我进行了一些调试，并为 Spring Security 和框架的其他部分找到了不同的记录器。
例如，在org.springframework.data.jpa.repository.query.JpaQueryFactorySpring 中使用记录器org.apache.logging.slf4j.Log4jLogger（在我的配置中设置为 DEBUG），但 Spring 安全使用org.apache.commons.logging.impl.Jdk14Logger例如 in org.springframework.security.web.FilterChainProxy（尽管我的 log4j2 配置设置为 INFO）。

所以我试图调试到FilterChainProxy分配记录器的代码中。但不幸的是，代码要么从未到达，要么我的断点不起作用。我猜是第二个。

Answer 1

我自己找到了问题的原因：
Spring广泛使用slf4J进行日志记录。为此，我在我的项目中包含了一个桥，它运行良好，并在我的问题中生成日志输出。
但是 Spring Security（也可能是 Spring 的其他部分）使用Apache Commons Logging这本身没有问题，因为Spring 5附带了spring.jcl，它是从Apache Commons Logging到log4J2 的桥梁。
但这是邪恶的事情：我引入了另一个对common-logging具有传递依赖关系的库因此将“Apache Commons Logging”的直接实现包含在我的项目中。所以我的org.apache.commons.logging.LogFactory类路径中有两个不同的类。Spring security 决定使用commons-logging 中的实现而不是spring-jcl 中的实现，因此我的 log4j-configuration 不会影响 Spring security 的记录器。

实际上我所要做的就是在我的构建文件中排除commons-logging并让spring-jcl再次完成它的工作。