Thursday, September 13, 2007

Turning on Hibernate Logging using Seam on JBoss 4.2

At some point, you're going to need to see the sql and the bind variables that hibernate is using. When running Seam on JBoss AS 4.2 and above, there are a couple things you need to do. First, add the following lines to <jboss home>/server/default/conf/jboss-log4j.xml

<category name="org.hibernate">  
<priority value="TRACE"/>
<appender-ref ref="HIBERNATE"/>
</category>


This tells log4j to start logging hibernate at a very high detail.
Next, make sure persistence-dev.xml has the hibernate.show_sql property set to true.

<persistence-unit name="AutoPropPass5">
<provider>org.hibernate.ejb.HibernatePersistence</provider>
<jta-data-source>java:/AutoPropPass5Datasource</jta-data-source>
<properties>
<property name="hibernate.hbm2ddl.auto" value="validate"/>
<property name="hibernate.cache.use_query_cache" value="true"/>
<property name="hibernate.show_sql" value="true"/> <============ HERE
<property name="jboss.entity.manager.factory.jndi.name" value="java:/AutoPropPass5EntityManagerFactory"/>
</properties>
</persistence-unit>


Then, add commons-logging.jar to the project's war lib directory and tweak build.xml to include this jar in the deployment:

<copy todir="${war.dir}/WEB-INF/lib">
<fileset dir="${lib.dir}">
<include name="ajax4jsf*.jar" />
<include name="richfaces*.jar" />
<include name="oscache*.jar" />
<include name="commons-digester-*.jar" />
<include name="commons-beanutils-*.jar" />
HERE ============> <include name="commons-logging*.jar" />
<include name="jsf-facelets.jar" />
<include name="jboss-seam-*.jar" />
<exclude name="jboss-seam-gen.jar" />
</fileset>
</copy>


When this is all in place, you should be able to see output like the following in <jboss home>/server/default/log/server.log:

2007-09-13 09:34:55,854 TRACE [org.hibernate.type.StringType] binding 'updi' to parameter: 1
2007-09-13 09:34:56,823 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-09-13 09:34:56,823 TRACE [org.hibernate.jdbc.AbstractBatcher] closing statement
2007-09-13 09:34:56,823 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-09-13 09:34:56,823 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-09-13 09:34:56,823 DEBUG [org.hibernate.util.JDBCExceptionReporter] could not execute query [select pass0_.PASS_ID as PASS1_35_, pass0_.ADDRESS as ADDRESS35_, pass0_.state as state35_, pass0_.VERSION as VERSION35_, pass0_.reason as reason35_, pass0_.status as status35_, pass0_.DESTINATION as DESTINAT7_35_, pass0_.INS_UPD_ID as INS8_35_, pass0_.INS_UPD_TS as INS9_35_, pass0_.PASS_HOLDER_PID as PASS17_35_, pass0_.PASS_CREATOR_PID as PASS18_35_, pass0_.HOLDER_GROUP_ID as HOLDER10_35_, pass0_.HOLDER_GROUP_SUP_PID as HOLDER11_35_, pass0_.CHECKOUT_DATE as CHECKOUT12_35_, pass0_.REMOVE_DATE as REMOVE13_35_, pass0_.DUE_DATE as DUE14_35_, pass0_.ADDRESS2 as ADDRESS15_35_, pass0_.CITY as CITY35_ from ERMPMGR.PP_PASS pass0_, ERMPMGR.PP_PERSON_MV person1_ where pass0_.PASS_HOLDER_PID=person1_.PERSON_ID and (upper(person1_.FULL_NAME) like upper(?+'%'))]
java.sql.SQLException: ORA-01722: invalid number

at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:124)
at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:304)
at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:271)
at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:625)
...


Notes:

  • Older versions of JBoss used a different file than jboss-log4j.xml (perhaps log4j.xml) and perhaps put a log4j.properties in the META-INF dir.

  • TRACE is used instead of DEBUG which worked in prior versions.

  • I'm not positive the {hibernate.show_sql bit is required, but seam-gen puts it in there by default.


In case your wondering why I was getting the "invalid number" error, it's because Oracle uses the || symbol for string concatenation, not +. When I fixed that, it started working.

9 comments:

Clark Updike said...

Man, I've gotta say, putting code into blog postings here is a real PITA. If anyone has suggestions on how to do, please let me know. Guess I could always roll some CSS, but after using wikis with good editors, that's like the dark ages.

Dan Allen said...

Okay, here is how this logging thing actually works:

You don't need any logging libraries in your WAR file. All of the logging is handled at the application server level. That's just how it is with JBoss AS. There are ways around it. See the JBoss at Work book for more info.

The jboss-log4j.xml file that you need to edit resides in $JBOSS_HOME/server/default/conf for the default domain

You can either set the Hibernate logging in the Log4j configuration or in the Hibernate property, but not both. Here are the rules:

1. If you set the org.hibernate.SQL category in jboss-log4j.xml to DEBUG, Hibernate will log the SQL statements. By setting the org.hibernate.SQL category, the Hibernate property hibernate.show_sql has no effect.

2. If you don't set the org.hibernate.SQL category at all in the jboss-log4j.xml, Hibernate will use the hibernate.show_sql property to determine whether or not to log the SQL statements.

You can also format the SQL by setting the Hibernate property hibernate.format_sql to true. This property works regardless of how you enable SQL logging.

Anonymous said...

OK, so you've both done the EASY part, getting logging turned on. Anybody could do that with hibernate.show_sql or the other way you showed.

Here's the hard part - how do you get what Hibernate calls the "bind parameters" - that is, the values put into the ? parameter markers in the prepared statements - to print out?

Thanks.

Clark Updike said...

Perhaps you missed it, but the example demonstrates the output of the binding operation. Look at the first line of the log output:
binding 'updi' to parameter: 1
That is the binding value.

Anonymous said...

FWIW, here's what I added to my (4.2.2.GA) $jb/server/default/conf/jboss-log4j.xml, right after the
"<!-- Limit categories -->" comment:


<category name="org.hibernate.SQL">

<priority value="DEBUG"/>

<appender-ref ref="CONSOLE"/>

</category>

<!-- enable type binding (what real users call parameter marker values).

*** This is VERY VERBOSE so use with caution!

-->

<category name="org.hibernate.type">

<priority value="TRACE"/>

<appender-ref ref="CONSOLE"/>

</category>

With or without the appender-refs, and with the hibernate.show_sql in persistence.xml, I get zero SQL output. Nada. Not just no bind parameters, but not even the formatted SQL with ? that I got before. Dan, have I failed to follow your directions to the letter? Thx.

Anonymous said...

Hmmm, you're right I did not see that, and I'm very surprised to see it without any mention of org.hibernate.type. I guess in your case you're getting that by 'inheritance' for your 'org.hibernate' category.

So I copied your setup (except using the CONSOLE logger since there is no HIBERNATE logger in my 4.2.2.GA version of jboss-log4j.xml, and it's now otherwise AFAICS identical to your setup. I am not getting the bind parameters.

Anonymous said...

Gaah, I was looking in the wrong log. Yes, it's all there now. Thanks, and sorry for the noise.

Anonymous said...

BTW, one last note, Dan is right that you do not need to add commons-logging.jar to your WAR app. I removed it and reloaded the app and the log file still updates.

Clark Updike said...

No problem... glad you got what you needed. Regarding my configuration (versus Dan's), I was flaying and when I finally got mine to work, it was hard to figure out what I had done that I didn't need to do--version differences were messing me up too. So I have no doubt that I had some noise in my approach.