Logback RollingFileAppender does not log Hibernate messages

Question

I have the following logback.xml:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
        </pattern>
    </encoder>
</appender>

<appender name="FILE"
    class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>C:/logs/external-web-services.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <!-- daily rollover -->
        <fileNamePattern>C:/logs/external-web-services.%d{yyyy-MM-dd}.log
        </fileNamePattern>
        <maxHistory>30</maxHistory>
    </rollingPolicy>
    <append>true</append>
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
        </pattern>
    </encoder>
</appender>

<logger name="org.hibernate.SQL" additivity="false">
    <level value="DEBUG" />
    <appender-ref ref="FILE" />
</logger>

<logger name="org.hibernate.type" additivity="false">
    <level value="DEBUG" />
    <appender-ref ref="FILE" />
</logger>

<root level="DEBUG">
    <appender-ref ref="STDOUT" />
    <appender-ref ref="FILE" />
</root>

I want to log Hibernate sql queries in my log file. I only see Hibernate queries in console when running from Eclipse (also in JBoss log file server.log, but this is something else I do not understand). In my log file (external-web-services.log) only my log messages are printed. No Hibernate message is ever printed. In eclipse I get the following:

11:50:05,367 INFO  [stdout] (default task-9) Hibernate: 
11:50:05,367 INFO  [stdout] (default task-9)     select
11:50:05,367 INFO  [stdout] (default task-9)         ftibssettl0_.settlcycleinstanceid as settlcycleinstance1_3_,
11:50:05,367 INFO  [stdout] (default task-9)         ftibssettl0_.endtime as endtime2_3_,
11:50:05,367 INFO  [stdout] (default task-9)         ftibssettl0_.PARTSET_0_PART as PARTSET_3_3_,
11:50:05,367 INFO  [stdout] (default task-9)         ftibssettl0_.PARTSET_1_PART as PARTSET_4_3_,
11:50:05,367 INFO  [stdout] (default task-9)         ftibssettl0_.PARTSET_2_PART as PARTSET_5_3_,
11:50:05,367 INFO  [stdout] (default task-9)         ftibssettl0_.PARTSET_3_PART as PARTSET_6_3_,
11:50:05,367 INFO  [stdout] (default task-9)         ftibssettl0_.PARTSET_4_PART as PARTSET_7_3_,
11:50:05,367 INFO  [stdout] (default task-9)         ftibssettl0_.settlcycletemplateid as settlcycletemplate8_3_,
11:50:05,368 INFO  [stdout] (default task-9)         ftibssettl0_.settlementdate as settlementdate9_3_,
11:50:05,368 INFO  [stdout] (default task-9)         ftibssettl0_.starttime as starttime10_3_,
11:50:05,368 INFO  [stdout] (default task-9)         ftibssettl0_.status as status11_3_ 
11:50:05,368 INFO  [stdout] (default task-9)     from
11:50:05,368 INFO  [stdout] (default task-9)         ibsprod.FT_IBS_SETTL_CYCLE_INSTANCE ftibssettl0_ 
11:50:05,368 INFO  [stdout] (default task-9)     where
11:50:05,368 INFO  [stdout] (default task-9)         ftibssettl0_.settlementdate=?

11:50:05,417 INFO  [stdout] (default task-9) 11:50:05.417 [default task-9] DEBUG g.d.n.s.CashMovementReportService - filterAndMarkCashMovements elapsed time: PT0.017S

What is strange about this log is that the format of the Hibernate message is not the format that I define in logback.xml encoder pattern, which can be seen in the last line of the log, which is my application's log message

Other Info:

I am using JBoss so I need to exclude JBoss own logging subsystem so that logback works, I am using the file jboss-deployment-structure.xml:

<jboss-deployment-structure>
  <deployment>
    <exclude-subsystems>
        <subsystem name="logging" />
    </exclude-subsystems>
  </deployment>
</jboss-deployment-structure>

I am using JPA so in case this might help this is my persistence.xml file:

<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<persistence xmlns="http://xmlns.jcp.org/xml/ns/persistence"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence
http://xmlns.jcp.org/xml/ns/persistence/persistence_2_1.xsd"
version="2.1">

<persistence-unit name="external-ws" transaction-type="JTA">
    <description>Oracle Persistence Unit</description>
    <provider>org.hibernate.ejb.HibernatePersistence</provider>
    <jta-data-source>${ds.name}</jta-data-source>
    <exclude-unlisted-classes>false</exclude-unlisted-classes>
    <properties>
        <property name="hibernate.default_schema" value="${ds.schema}"/>
        <property name="hibernate.show_sql" value="true" />
        <property name="hibernate.format_sql" value="true" />
        <property name="org.hibernate.flushMode" value="manual"/>
    </properties>
</persistence-unit>

Answer 1

Try adding:

<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
  <level>TRACE</level>
</filter>

to both the CONSOLE and the FILE appender. The default threshold is WARN.

You can also check if this is the configuration file log4j uses. It may be that a different file might be loaded, due to class loading miss configurations.

The ch.qos.logback.classic.util.ContextInitializer has a:

public void configureByResource(URL url) {

method you can try debugging at runtime to check which configuration file is actually loaded.

Also, try removing:

<property name="hibernate.show_sql" value="true" />
<property name="hibernate.format_sql" value="true" />

since those should only print to console.