Search code examples
javaspringhibernatelogginglogback

Logback shows DEBUG output with root at level INFO when org.hibernate.SQL logger configured

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.

Solution

  • 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