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>

Why do you have `additivity="false"` in the logback config? – skaffman Aug 27 '14 at 00:06 — skaffman, Aug 27 '14 at 00:06

score 27 · Accepted Answer · edited Aug 21 '17 at 11:31

27

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>

edited Aug 21 '17 at 11:31

uwolfer

4,356
1
25
40

answered Aug 27 '14 at 18:15

CodeMed

9,527
70
212
364

2

So what helped was removing `additivity="false"`? – Abdull Apr 25 '17 at 15:01
--> - I bet the --> is redundant – mvmn May 08 '17 at 21:54
1

I like ``, 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. – andy Jan 09 '19 at 23:25

score 3 · Answer 2 · answered Aug 27 '14 at 00:40

3

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

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

answered Aug 27 '14 at 00:40

Andrey M

53
7

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 Aug 27 '14 at 02:45
do you have any other suggestions? – CodeMed Aug 27 '14 at 16:29
This answer + removing the additivity=false property did the trick for me. – ibai Jul 17 '17 at 15:58

score 3 · Answer 3 · answered Feb 12 '17 at 20:23

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.

logging hibernate parameter values using logback and slf4j

3 Answers3