Hibernate sql output in Server Log and Console

[devq]

Hi,

I'm using hibernate and trying to output the sql and any relevant comments to the console and server log. I'm using a log4j.xml file to configure log4j (pasted below).

Initially I was using the log4j.properties file and including the statement:

log4j.logger.org.hibernate.type=debug

This was working fine locally giving me the following output:

Hibernate: update USER_PROFILE set USER_ID=? where id=?
2007-04-17 14:04:34,927 DEBUG [org.hibernate.type.LongType] - <binding '1000003' to parameter: 1>
2007-04-17 14:04:34,927 DEBUG [org.hibernate.type.LongType] - <binding '88900' to parameter: 2>

Now, however I want to just use log4j.xml and was hoping that I could get the same output using:

<category name="org.hibernate.type">
 <priority value="DEBUG"/>
 </category>

Unfortunately this has not worked for me. and I have lost the portion underlined above.

Is it possible to get this output working on the server?

Thanks in advance!

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">


<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">

 <!-- ================================= -->
 <!-- Preserve messages in a local file -->
 <!-- ================================= -->

 <!--*****************************************************************************-->
 <!-- MY LOG FILE APPENDER-->

 <appender name="My_Log" class="org.jboss.logging.appender.DailyRollingFileAppender">
 <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
 <param name="File" value="${jboss.server.log.dir}/my_log.log"/>
 <param name="Append" value="true"/>

 <!-- Rollover at midnight each day -->
 <param name="DatePattern" value="'.'yyyy-MM-dd"/>

 <layout class="org.apache.log4j.PatternLayout">
 <!-- The default pattern: Date Priority [Category] Message\n -->
 <param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>

 </layout>

 </appender>



 <!--****************************************************************************-->

 <!-- SERVER LOG FILE APPENDER-->
 <!-- A time/date based rolling appender -->

 <appender name="FILE" class="org.jboss.logging.appender.DailyRollingFileAppender">
 <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
 <param name="File" value="${jboss.server.log.dir}/server.log"/>
 <param name="Append" value="false"/>

 <!-- Rollover at midnight each day -->
 <param name="DatePattern" value="'.'yyyy-MM-dd"/>

 <!-- Rollover at the top of each hour
 <param name="DatePattern" value="'.'yyyy-MM-dd-HH"/>
 -->

 <layout class="org.apache.log4j.PatternLayout">
 <!-- The default pattern: Date Priority [Category] Message\n -->
 <param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>

 </layout>
 </appender>


 <!-- ============================== -->
 <!-- Append messages to the console -->
 <!-- ============================== -->

 <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
 <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
 <param name="Target" value="System.out"/>
 <param name="Threshold" value="INFO"/>

 <layout class="org.apache.log4j.PatternLayout">
 <!-- The default pattern: Date Priority [Category] Message\n -->
 <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
 </layout>
 </appender>


 <!-- ================ -->
 <!-- Limit categories -->
 <!-- ================ -->

 <!-- Limit the org.apache category to INFO as its DEBUG is verbose -->
 <category name="org.apache">
 <priority value="INFO"/>
 </category>

 <!-- Limit the org.jboss.serial (jboss-serialization) to INFO as its DEBUG is verbose -->
 <category name="org.jboss.serial">
 <priority value="INFO"/>
 </category>

 <!-- Limit the org.jgroups category to WARN as its INFO is verbose -->
 <category name="org.jgroups">
 <priority value="WARN"/>
 </category>

 <!-- Limit the jacorb category to WARN as its INFO is verbose -->
 <category name="jacorb">
 <priority value="WARN"/>
 </category>


 <!-- Limit the JSR77 categories -->
 <category name="org.jboss.management">
 <priority value="INFO"/>
 </category>

 <!-- Log the actual Hibernate Query Language (HQL) expression -->
 <category name="org.hibernate.impl.SessionImpl">
 <priority value="DEBUG">
 </priority>
 </category>

<!-- Log the substitution parameters in the HQL expression -->
 <category name="org.hibernate.engine.QueryParameters">
 <priority value="DEBUG">
 </priority>
 </category>

 <category name="org.hibernate">
 <priority value="DEBUG"/>
 </category>


<!--****************************************************-->
<!-- Set up my logger -->

 <logger name="myLogger">
 <level value="info"/>
 <appender-ref ref="My_Log"/>
 </logger>

<!--****************************************************-->

 <!-- ======================= -->
 <!-- Setup the Root category -->
 <!-- ======================= -->

 <root>
 <appender-ref ref="CONSOLE"/>
 <appender-ref ref="FILE"/>
 </root>


</log4j:configuration>

[jfrankman]

I am having the same problem. Did you ever get this resolved?

[jdijkmeijer]

I do have exactly the same problem:

I checked the jboss-log4j.xml, checked for Threshold settings etc. I do see the org.hibernate.pretty.Printer output reacting to changes to log4j settings but not the org.hibernate.type.[types].
I also decompiled the org.hibernate.type.StringType /Applications/jboss-4.2.2.GA/server/default/lib/Hibernate3.jar, but I dont see the logging statements in there.
Is there a fix?

regards,
Jeroen.
ENV:
13:47:21,453 INFO [Server] Release ID: JBoss [Trinity] 4.2.2.GA (build: SVNTag=JBoss_4_2_2_GA date=200710221139)
13:47:21,732 INFO [ServerInfo] Java version: 1.5.0_07,Apple Computer, Inc.

[jaikiran]

Set the level for org.hibernate.type to TRACE as follows

<category name="org.hibernate.type">
 <priority value="TRACE"/>
 </category>

More details can be found at http://opensource.atlassian.com/projects/hibernate/browse/HHH-2835

Also, if you look at the code in org.hibernate.type.NullableType, you will find that there is a check to see whether TRACE level logging is enabled.

[jdijkmeijer]

Ahh that explains it, still wondering why @work I can use debug, we use there commons-logging and spring together with hibernate3.

Of course the Threshold in the appender needed to be adjusted as well.

Looking at the code, I'm wondering if it would be valuable if you can specify whether you see the returning or binding values?

thanks & regards,
Jeroen.

[jaikiran]

"jdijkmeijer" wrote:
still wondering why @work I can use debug, we use there commons-logging and spring together with hibernate3.

As mentioned in the bug report, the behaviour depends on the version of log4j being used. Not sure how it behaves with commons-logging.

"jdijkmeijer" wrote:
Looking at the code, I'm wondering if it would be valuable if you can specify whether you see the returning or binding values?

Sorry, i did not understand your question. Are you asking what the code in that class of Hibernate looks like?

[jdijkmeijer]

Wish I had paid more attention during English classes.
I'll try to rephraze.

I was actually wondering whether people are looking for an extra log type possibility like:

org.hibernate.type -> log binding and returning statements
org.hibernate.type.binding -> only log binding variables.
(and possibly even differentiate between binding variables in insert stmts and query stmts)
org.hibernate.type.returning -> only log returning variables.
I would appreciate it, I looked into the source code of the nullable type and it doesnt look very complicated to implement, I'm not sure on performance impact though.

regards,
jeroen.

[jaikiran]

"jdijkmeijer" wrote:
Wish I had paid more attention during English classes.
I'll try to rephraze.

I was actually wondering whether people are looking for an extra log type possibility like:

org.hibernate.type -> log binding and returning statements
org.hibernate.type.binding -> only log binding variables.
(and possibly even differentiate between binding variables in insert stmts and query stmts)
org.hibernate.type.returning -> only log returning variables.
I would appreciate it, I looked into the source code of the nullable type and it doesnt look very complicated to implement, I'm not sure on performance impact though.

Thanks for rephrasing, i understand your question now.

Actually, this is something which will have to be taken up with the Hibernate team. You can post this question on their forums at http://forum.hibernate.org/viewforum.php?f=1&sid=75953b08bc9d5a402ac19a17c852001c