Logback shows DEBUG output with root at level INFO

Question

Why would logback allow DEBUG output thru a root logger set to level INFO?

The context is a spring-boot-starter project using Hibernate. The POM names logback-classic and logback-core at version 1.2.0. The following config file is on its classpath (src/main/resources), sets the root logger to INFO level.

logback-test.xml:

<configuration scan="true" debug="false">
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>logs/test.log</file>
    <encoder>
      <pattern>%d{&quot;yyyy-MM-dd'T'HH:mm:ss.SSSXXX&quot;, UTC} [%thread] %-5level %logger{5} - %msg%n</pattern>
    </encoder>
  </appender>
  <root level="INFO">
    <appender-ref ref="FILE" />
  </root>
  <logger name="org.hibernate.SQL" level="DEBUG" />
</configuration>

Plenty of INFO/WARN/ERROR messages come thru in the file during a JUnit test. But I'm surprised to see the following DEBUG output from org.hibernate.SQL, which is the ONLY package that contributes debug-level output. I thought I would have to set the root logger to level DEBUG to allow this; I figured level INFO would block it:

2018-09-18T13:31:02.596Z [http-nio-auto-1-exec-4] DEBUG o.h.SQL - delete from C_NOTIF_XYZ where ID=?

Under the covers it appears that Hibernate uses org.jboss.logging.Logger via annotations, see https://github.com/hibernate/hibernate-orm/blob/master/hibernate-core/src/main/java/org/hibernate/internal/CoreLogging.java

Due to use of annotations, I'm not confident I found the exact class that creates the Delete output shown above. I see from googling that some people suggest an interaction of logging shim classes; but I'm not sure.

Very similar SO question (so I'm not alone :) but no answer: Using logback, debug messages are still being logged though root level is set to "Error"

Thanks in advance for any hints.

Answer 1

From the docs:

The effective level for a given logger L, is equal to the first non-null level in its hierarchy, starting at L itself and proceeding upwards in the hierarchy towards the root logger.

So, you can define an effective level for a logger which overrides the root level. The behaviour you are seeing is default Logback behaviour.

If you want to disable the DEBUG logging from org.hibernate.SQL logger then either:

• Remove the org.hibernate.SQL logger configuration since this will cause the org.hibernate.SQL logger to assume the root logger level
• Assign the org.hibernate.SQL logger a log level other than DEBUG

Answer 2

At the moment I don't find the reference to the documentation, but I confirm this mode of operation: behavior for ancestor loggers reached through additivity, which by default is set to true, skips log level checks. Then the log message is sent to the root logger regardless of his log level.

Answer 3

Remove this line:

  <logger name="org.hibernate.SQL" level="DEBUG" />