logging hibernate parameter values using logback and slf4j

Question

I use hibernate, spring mvc, and eclipse. In my eclipse console, the hibernate sql displays in the form of:

Hibernate: insert into some_table (fieldname1, fieldname2, fieldname3, fieldname4)  
values (?, ?, ?, ?)

How can I get the console to print out the values that are being inserted in the place of the question marks? I am committed to using slf4j and logback for the logging in my app.

Here is my logback.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds">

    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
        <resetJUL>true</resetJUL>
    </contextListener>

    <!-- To enable JMX Management -->
    <jmxConfigurator/>

    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%-5level %logger{0} - %msg%n</pattern>
        </encoder>
    </appender>

    <!--<logger name="org.hibernate" level="debug"/> -->
    <logger name="mypackagename.myappname" level="debug"/>
    <logger name="org.hibernate.SQL" additivity="false" level="DEBUG" />
    <logger name="org.hibernate.type" additivity="false" level="TRACE" />

    <root level="info">
        <appender-ref ref="console"/>
    </root>
</configuration>

Solution 1

The correct working answer turned out to be:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds">

    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
        <resetJUL>true</resetJUL>
    </contextListener>

    <!-- To enable JMX Management -->
    <jmxConfigurator/>

    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%-5level %logger{0} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="mypackagename.myappname" level="TRACE"/>
    <logger name="org.hibernate.SQL" level="DEBUG" />
    <logger name="org.hibernate.type" level="TRACE" />

    <root level="info">
        <appender-ref ref="console"/>
    </root>
</configuration>

Solution 2

Configure org.hibernate.type.descriptor.sql.BasicBinder package to log TRACE level:

 <logger name="org.hibernate.type.descriptor.sql.BasicBinder" additivity="false" level="TRACE" />

Solution 3

This is some info about the the 2 offered answers. Both worked for me.

For printing the query you want:

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

To print it "pretty" you can use the jpaProperties.put("hibernate.format_sql", true|false); More info in [https://docs.jboss.org/hibernate/stable/core.old/reference/en/html/configuration-optional.html]

Now regarding the values. The accepted:

<logger name="org.hibernate.type" additivity="false" >
    <level value="TRACE" />
    <appender-ref ref="SQLROLLINGFILE" />
    <appender-ref ref="STDOUT" />
</logger>

The output would be:

2017-02-12 14:16:57 DEBUG org.hibernate.SQL - 
    select
        producttyp0_.idProductType as idProduc1_25_1_,
        producttyp0_.deleted as deleted2_25_1_,
        producttyp0_.description as descript3_25_1_,
        producttyp0_.name as name4_25_1_,
        products1_.idProductType as idProduc6_25_3_,
        products1_.idProduct as idProduc1_24_3_,
        products1_.idProduct as idProduc1_24_0_,
        products1_.deleted as deleted2_24_0_,
        products1_.maxQty as maxQty3_24_0_,
        products1_.name as name4_24_0_,
        products1_.price as price5_24_0_,
        products1_.idProductType as idProduc6_24_0_ 
    from
        ProductType producttyp0_ 
    left outer join
        Product products1_ 
            on producttyp0_.idProductType=products1_.idProductType 
    where
        producttyp0_.idProductType=?
2017-02-12 14:16:57 TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [INTEGER] - [35]
2017-02-12 14:16:57 TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([idProduc1_24_0_] : [INTEGER]) - [null]
2017-02-12 14:16:57 TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([deleted2_25_1_] : [INTEGER]) - [0]
2017-02-12 14:16:57 TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([descript3_25_1_] : [VARCHAR]) - [desc]
2017-02-12 14:16:57 TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([name4_25_1_] : [VARCHAR]) - [c0my6zko[test]]
2017-02-12 14:16:57 TRACE o.h.t.descriptor.sql.BasicExtractor - extracted value ([idProduc6_25_3_] : [INTEGER]) - [null]

---

And the other offered solution

<logger name="org.hibernate.type.descriptor.sql.BasicBinder" additivity="false" level="TRACE" >
    <level value="TRACE" />
    <appender-ref ref="SQLROLLINGFILE" />
    <appender-ref ref="STDOUT" />
</logger>

The output would be:

2017-02-12 14:18:55 DEBUG org.hibernate.SQL - 
    select
        producttyp0_.idProductType as idProduc1_25_1_,
        producttyp0_.deleted as deleted2_25_1_,
        producttyp0_.description as descript3_25_1_,
        producttyp0_.name as name4_25_1_,
        products1_.idProductType as idProduc6_25_3_,
        products1_.idProduct as idProduc1_24_3_,
        products1_.idProduct as idProduc1_24_0_,
        products1_.deleted as deleted2_24_0_,
        products1_.maxQty as maxQty3_24_0_,
        products1_.name as name4_24_0_,
        products1_.price as price5_24_0_,
        products1_.idProductType as idProduc6_24_0_ 
    from
        ProductType producttyp0_ 
    left outer join
        Product products1_ 
            on producttyp0_.idProductType=products1_.idProductType 
    where
        producttyp0_.idProductType=?
2017-02-12 14:18:55 TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [INTEGER] - [36]

Personally I like the 2nd one because is less info (avoiding the o.h.t.descriptor.sql.BasicExtractor), but its up to the project.

Hope it gives a little more info about what to include.

Comments

[skaffman]

Why do you have additivity="false" in the logback config?

[CodeMed]

That did not fix it. I still have the same problem. Even after trying a few combinations of just that logger, or that logger plus combinations of the others, etc. Are you able to test the code in your own eclipse hibernate installation to find something that works? Do the version numbers in pom.xml make a difference?

[CodeMed]

do you have any other suggestions?

[Abdull]

So what helped was removing additivity="false"?

[mvmn]

<logger name="org.hibernate.type" level="TRACE" />--> - I bet the --> is redundant

[ibai]

This answer + removing the additivity=false property did the trick for me.

[andy]

I like <logger name="org.hibernate.type" level="TRACE" />, too. But be careful, when you have blobs. It's logging tons of number sequences (String representation of Blob type is array of decimal numbers) that blow up your log file.