log4j - Hibernate messages are (mostly) MIA

bill.horan · **Joined:** Thu Dec 08, 2005 3:54 pm **Posts:** 11

Hibernate version: 3.0.5

The generated SQL (show_sql=true):

[8/23/06 14:08:10:462 CDT] 4e35961e SystemOut O Hibernate: select codevalues0_.FK_COD_ID as FK10_1_, ...
codevalues0_ where codevalues0_.FK_COD_ID=?

Debug level Hibernate log excerpt:

Missing. That's the problem. We've been using Hibernate for about a year - and it all works great - except we've never been able to get Hibernate to produce anything beyond the show_sql level of log4j logging.

We're running a basic Struts app on a WebSphere 5.1 server. It's nothing fancy - just JSPs, Struts w/Tiles, Hibernate, and log4j.

We're using log4j to do our own project logging. We're not using Commons logging - we're using log4j directly. Our own log4j messages show up as desired and are controlled just fine from the log4j.properties file.

We'd like to see the Hibernate logging messages. We're following the hibernate instructions for log4j by putting the log4j.properties file in the same directory as our hibernate.cfg.xml file. And we've copied the log4j settings from the example hibernate log4j properties file from the etc directory of the hibernate distribution.

Here's a slice of our log4j properties file:

log4j.rootLogger=DEBUG, stdout
log4j.logger.org.our_group.our_project.persistence=DEBUG
log4j.logger.org.our_group.our_project.notification.delivery=INFO
...
log4j.logger.org.hibernate=debug

### log HQL query parser activity
log4j.logger.org.hibernate.hql.ast.AST=debug

### log just the SQL
log4j.logger.org.hibernate.SQL=debug

### log JDBC bind parameters ###
log4j.logger.org.hibernate.type=debug
...

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%t %-5p %x %c - %m%n

The problem is - the only time we see log4j output from Hibernate is when we set show_sql=true in our hibernate.cfg file. And that's all the output we ever see from Hibernate - just the templates of the SQL queries with the questions marks instead of the values bound to those queries at run time.

As you can see from our log4j.properties file, we're running the logging at the DEBUG level, and we've asked Hibernate to show us the bound values of the query parameters:

log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.type=debug

But no matter what log4j.properties settings we use, we don't see any more or any fewer hibernate messages. The only value that seems to have any effect on the hibernate log4j messages is the show_sql value from the hibernate.cfg file.

Any ideas on why hibernate is ignoring our log4j.properties file while the rest of our application runs with that very same log4j file just fine?

jwisard · **Joined:** Tue Oct 19, 2004 11:04 am **Posts:** 22

I am having this exact same problem. Any help would be greatly appreciated. I've tried everything under the sun I can think to try.

UPDATE:

log4j is picking up my log4j.properties file appropriately. I can comment out this:

### log just the SQL
log4j.logger.org.hibernate.SQL=debug

And my log will no longer show the generated sql. However, no matter what I do with the bind parameters option, it won't show the bind parameters.

### log JDBC bind parameters ###
log4j.logger.org.hibernate.type=debug

bill.horan · **Joined:** Thu Dec 08, 2005 3:54 pm **Posts:** 11

UPDATE

I still haven't solved the problem, but I'm trying.

I upgraded from log4j 1.2.8 to 1.2.13 (to upgrade to a version of log4j that includes the trace level)

I edited my log4j.properties file to set the levels to "all" instead of "info" or "debug"

I added the following option to my server startup:

-Dlog4j.debug

This traces the log4j configuration steps. This trace shows that log4j finds and process my log4.properties file without trouble:

Code:

[8/29/06 9:15:53:415 CDT]  16ce535 SystemOut     O log4j: Trying to find [log4j.xml] using context classloader 
com.ibm.ws.classloader.CompoundClassLoader@b44653d
   Local ClassPath: C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\classes;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\antlr-2.7.4.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-beanutils-1.7.0.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-digester-1.6.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-fileupload-1.0.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-javaflow-20060411.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-validator-1.1.4.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\itext-1.3.1.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jasperreports-1.2.5.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jaxen-1.0-FCS-full.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jh.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jsp-api-2.0.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jstl-1.1.2.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\oro-2.0.8.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\poi-2.5.1-final-20040804.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\saxpath-1.0-FCS.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\srscustomtags-SNAPSHOT.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\srsframeworksjasperreports-1.0.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\standard-1.1.2.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\struts-1.2.7.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\struts-el-1.2.7.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\taglibs-datetime.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\taglibs-mailer.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\taglibs-string.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\utility.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent;
   Delegation Mode: PARENT_FIRST.
[8/29/06 9:15:53:415 CDT]  16ce535 SystemOut     O log4j: Trying to find [log4j.xml] using 
com.ibm.ws.classloader.CompoundClassLoader@bcfe53d
   Local ClassPath: C:\java\develop\projects\EASsvn\EASBusinessProcess\bin;C:\java\develop\projects\EASsvn\EASDomain\bin;C:\java\develop\projects\EASsvn\EASProperties\bin;C:\java\develop\projects\EASsvn\EASEar\log4j-1.2.13.jar;C:\java\develop\projects\EASsvn\EASEar\antlr-2.7.5H3.jar;C:\java\develop\projects\EASsvn\EASEar\asm.jar;C:\java\develop\projects\EASsvn\EASEar\cglib-2.1.jar;C:\java\develop\projects\EASsvn\EASEar\commons-collections-2.1.1.jar;C:\java\develop\projects\EASsvn\EASEar\dom4j-1.6.jar;C:\java\develop\projects\EASsvn\EASEar\ehcache-1.1.jar;C:\java\develop\projects\EASsvn\EASEar\junit-3.8.1.jar;C:\java\develop\projects\EASsvn\EASEar\hibernate-3.0.5.jar;C:\java\develop\projects\EASsvn\EASWeb\EASNotification.jar;
   Delegation Mode: PARENT_FIRST class loader.
[8/29/06 9:15:53:415 CDT]  16ce535 SystemOut     O log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
[8/29/06 9:15:53:415 CDT]  16ce535 SystemOut     O log4j: Trying to find [log4j.properties] using context classloader 
com.ibm.ws.classloader.CompoundClassLoader@b44653d
   Local ClassPath: C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\classes;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\antlr-2.7.4.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-beanutils-1.7.0.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-digester-1.6.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-fileupload-1.0.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-javaflow-20060411.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\commons-validator-1.1.4.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\itext-1.3.1.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jasperreports-1.2.5.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jaxen-1.0-FCS-full.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jh.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jsp-api-2.0.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\jstl-1.1.2.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\oro-2.0.8.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\poi-2.5.1-final-20040804.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\saxpath-1.0-FCS.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\srscustomtags-SNAPSHOT.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\srsframeworksjasperreports-1.0.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\standard-1.1.2.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\struts-1.2.7.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\struts-el-1.2.7.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\taglibs-datetime.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\taglibs-mailer.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\taglibs-string.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent\WEB-INF\lib\utility.jar;C:\java\develop\projects\EASsvn\EASWeb\WebContent;
   Delegation Mode: PARENT_FIRST.
[8/29/06 9:15:53:425 CDT]  16ce535 SystemOut     O log4j: Using URL [file:/C:/java/develop/projects/EASsvn/EASProperties/bin/log4j.properties] for automatic log4j configuration.
[8/29/06 9:15:53:455 CDT]  16ce535 SystemOut     O log4j: Reading configuration from URL file:/C:/java/develop/projects/EASsvn/EASProperties/bin/log4j.properties
[8/29/06 9:15:53:455 CDT]  16ce535 SystemOut     O log4j: Parsing for [root] with value=[ALL, stdout].
[8/29/06 9:15:53:455 CDT]  16ce535 SystemOut     O log4j: Level token is [ALL].
[8/29/06 9:15:53:455 CDT]  16ce535 SystemOut     O log4j: Category root set to ALL
[8/29/06 9:15:53:455 CDT]  16ce535 SystemOut     O log4j: Parsing appender named "stdout".
[8/29/06 9:15:53:495 CDT]  16ce535 SystemOut     O log4j: Parsing layout options for "stdout".
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Setting property [conversionPattern] to [%t %-5p %x %c - %m%n].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: End of parsing for "stdout".
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsed "stdout" options.
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.jdbc] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.jdbc set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.jdbc=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.type] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.type set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.type=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.transaction] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.transaction set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.transaction=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.connection.DriverManagerConnectionProvider] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.connection.DriverManagerConnectionProvider set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.connection.DriverManagerConnectionProvider=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.tool.hbm2ddl] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.tool.hbm2ddl set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.tool.hbm2ddl=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.SQL] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.SQL set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.SQL=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.hql] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.hql set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.hql=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.hql.ast.AST] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.hql.ast.AST set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.hql.ast.AST=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.srskansas.eas.notification.delivery] with value=[INFO].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [INFO].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.srskansas.eas.notification.delivery set to INFO
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.srskansas.eas.notification.delivery=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.srskansas.eas.persistence] with value=[DEBUG].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [DEBUG].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.srskansas.eas.persistence set to DEBUG
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.srskansas.eas.persistence=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Parsing for [org.hibernate.cache] with value=[all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Level token is [all].
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Category org.hibernate.cache set to ALL
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Handling log4j.additivity.org.hibernate.cache=[null]
[8/29/06 9:15:53:515 CDT]  16ce535 SystemOut     O log4j: Finished configuring.

I see log4j hibernate messages - plenty of them (especially now that I'm running at the "all" level so I see the "trace" messages) but I still never see the bound JDBC parameters in a SQL call

For example, here are some hibernate log4j messages I see:

Code:

[8/29/06 9:15:58:071 CDT]  16ce535 SessionFactor I org.hibernate.impl.SessionFactoryObjectFactory  Factory name: hibernate/SessionFactory
[8/29/06 9:15:58:071 CDT]  16ce535 NamingHelper  I org.hibernate.util.NamingHelper  JNDI InitialContext properties:{}
[8/29/06 9:15:58:071 CDT]  16ce535 SessionFactor I org.hibernate.impl.SessionFactoryObjectFactory  Bound factory to JNDI name: hibernate/SessionFactory
[8/29/06 9:15:58:071 CDT]  16ce535 SessionFactor W org.hibernate.impl.SessionFactoryObjectFactory  InitialContext did not implement EventContext
[8/29/06 9:15:58:252 CDT]  16ce535 WebSphereTran I org.hibernate.transaction.WebSphereTransactionManagerLookup  WebSphere 5.1
[8/29/06 9:15:58:252 CDT]  16ce535 SessionFactor I org.hibernate.impl.SessionFactoryImpl  Checking 0 named queries

...

Code:

[8/29/06 9:15:58:953 CDT]  16ce535 SystemOut     O Hibernate: select codetable0_.COD_ID as COD1_, codetable0_.CODE_NAME as CODE2_12_, codetable0_.DISPLAY_TITLE as DISPLAY3_12_, codetable0_.EFFECTIVE_DATE as EFFECTIVE4_12_, codetable0_.EXPIRATION_DATE as EXPIRATION5_12_, codetable0_.CREATED_BY as CREATED6_12_, codetable0_.CREATED_TIMESTAMP as CREATED7_12_, codetable0_.LAST_UPDATE_BY as LAST8_12_, codetable0_.LAST_UPDATED_TMST as LAST9_12_ from EADEV.EA_CODE codetable0_ where upper(codetable0_.CODE_NAME)=?

Notice how the Hibernate select debug messages ends with a ? instead of the actual value bound at run-time for that select? I still haven't found the secret hand-shake to see the runtime values that fill in the ?'s shown in the debug messages.

Maybe Hibernate never shows these values? Maybe we're never allowed to see the values used in the select SQL calls from hibernate?

CWitherow · **Posted:** Tue Aug 29, 2006 2:09 pm

Hibernate uses Commons logging.

Create commons-logging.properties with the following contents:

Code:

org.apache.commons.logging.Log=org.apache.commons.logging.impl.Log4JLogger

log4j.configuration=log4j.properties

and make sure commons-logging.jar is in your classpath. Commons logging will then defer to Log4j for the configuration.

Curtis ...

bill.horan · **Joined:** Thu Dec 08, 2005 3:54 pm **Posts:** 11

Thanks for the advice. I tried it out - but there was no difference. I already had a commons-logging jar file in my path (in the same directory as the log4j.jar file). Per your advice, I created a commons-logging.properties file with the suggested values. I put that properties file in the same directory as my log4j.properties file. And then I bounced the server.

I'm seeing plenty of Hibernate logging messages - the same Hibernate messages I already saw - just not the one I'm looking for. Maybe it doesn't exist? Maybe Hibernate never logs the values used in the generated SQL select calls?

When Hibernate shows me its generated SQL select calls, the debug messages look like this:

Code:

[8/29/06 13:40:56:522 CDT] 331d8778 SystemOut     O Hibernate: select codetable0_.COD_ID as COD1_, codetable0_.CODE_NAME as CODE2_12_, codetable0_.DISPLAY_TITLE as DISPLAY3_12_, codetable0_.EFFECTIVE_DATE as EFFECTIVE4_12_, codetable0_.EXPIRATION_DATE as EXPIRATION5_12_, codetable0_.CREATED_BY as CREATED6_12_, codetable0_.CREATED_TIMESTAMP as CREATED7_12_, codetable0_.LAST_UPDATE_BY as LAST8_12_, codetable0_.LAST_UPDATED_TMST as LAST9_12_ from EADEV.EA_CODE codetable0_ where upper(codetable0_.CODE_NAME)=?
...
[8/29/06 13:40:56:522 CDT] 331d8778 SystemOut     O Hibernate: select codevalues0_.FK_COD_ID as FK10_1_, codevalues0_.COV_ID as COV1_1_, codevalues0_.COV_ID as COV1_0_, codevalues0_.CDVALUE as CDVALUE13_0_, codevalues0_.DESCRIPTION as DESCRIPT3_13_0_, codevalues0_.EFFECTIVE_DATE as EFFECTIVE4_13_0_, codevalues0_.EXPIRATION_DATE as EXPIRATION5_13_0_, codevalues0_.CREATED_BY as CREATED6_13_0_, codevalues0_.CREATED_TIMESTAMP as CREATED7_13_0_, codevalues0_.LAST_UPDATED_BY as LAST8_13_0_, codevalues0_.LAST_UPDATED_TMST as LAST9_13_0_, codevalues0_.FK_COD_ID as FK10_13_0_ from EADEV.EA_CODE_VALUE codevalues0_ where codevalues0_.FK_COD_ID=?
...

My whole question is - how can I get Hibernate to log the values used to fill in the ? marks? We want to see the values Hibernate is using for each select as each select is executed. So far, we can't figure out how to make Hibernate turn on that piece of logging.

CWitherow · **Posted:** Wed Aug 30, 2006 3:21 pm

I thought I had this working until I retested after your last post. I found that it worked for "stand-alone" apps but not web apps.

The problem is caused by Websphere -- it uses a custom LogFactory implementation. I got it working:

1. Configure commons logging as I mentioned in my previous post;
2. Configure log4j -- BE PREPARED, once I got this going I had to set log levels for several packages that I had never seen log entries from before!

Code:

log4j.logger.org.hibernate.type=debug

is the correct directive for logging bind parameters;
3. Start your server w/

Code:

-Dorg.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl

See http://jakarta.apache.org/commons/logging/commons-logging-1.1/troubleshooting.html#Containers_With_Custom_LogFactory_Implementations for more information about using commons logging in Websphere.

Curtis ...

bill.horan · **Joined:** Thu Dec 08, 2005 3:54 pm **Posts:** 11

O frabjous day! Callooh! Callay!

I thought it might be a commons logging issue - but hadn't traced it down. Thanks for finding it/pointing it out!

In my searches, I saw various websites declaring the evil of commons logging and recommending the use of log4j directly.

Here were what I thought were good descriptions of some of the commons-logging issues in general:

http://www.qos.ch/logging/classloader.jsp
http://www.qos.ch/logging/thinkAgain.jsp - this one also has links to other articles supporting the removal of commons-logging from the face of the earth

Written as they were by the author of log4j I'm sure those two articles have no bias. (OK - so those articles may be biased - but after reading them I think they were fair and I'm convinced to stay far away from commons-logging.)

If any of the Hibernate core team are reading this - I (humbly) request two things:

1 (reasonable request) - on the Hibernate FAQ about how to configure log4j logging for Hibernate, please add a link to the WebSphere/Common-Logging issue pointed out by Curtis http://jakarta.apache.org/commons/logging/commons-logging-1.1/troubleshooting.html#Containers_With_Custom_LogFactory_Implementations

2 (unreasonable request - but I'm hoping anyway) - please drop the commons-logging API entirely and switch to log4j directly (or to the replacement for log4j when it arrives). I despair trying to count the wasted hours myself and other developers on this project wrestled with the log4j and hibernate configurations trying to coax the desired debug messages to appear - when the whole time it was a WebSphere/commons-logging collision causing the problem.

Thanks again Curtis!

jgodea · **Joined:** Thu Jun 15, 2006 2:15 pm **Posts:** 15

How do you start the server in the development environment with

-Dorg.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl

?

Thanks for the solution above. At least I can see the debug in standalone mode now.

CWitherow · **Posted:** Wed Oct 18, 2006 9:13 am

Create a system property in the server configuration.

Curtis ...

jgodea · **Joined:** Thu Jun 15, 2006 2:15 pm **Posts:** 15

I see how you can do that in WSAD. I am using RAD 6.0 and I don't see a way to set something like that. It looks like they may have removed that option.

tfolks · **Joined:** Mon Oct 16, 2006 8:47 pm **Posts:** 2

WAS includes commons-logging in it. If you haven't changed any classloader settings in your application, by default WAS will use a global default logging configuration that bypasses anything you configure with log4j.

My suggestion is simply to skip log4j and change org.hibernate.* logging levels through the WAS admin console. You can even do it at runtime on the fly.

However, you can successfully configure the included commons-logging or include your own in your application and configure it separately from WAS with log4j. Depending on the exact configuration you wish to have, it could involve changing classloader settings in your EAR/WAR or setting some properties in the META-INF of your WAR file.

If you are using WAS 6.x, look here: http://publib.boulder.ibm.com/infocente ... d_jcl.html

For WAS 5.1, look here: http://www-1.ibm.com/support/docview.ws ... -8&lang=en

This might seem like a pain, but once you learn what WAS is doing (and lets you do) with logging, it's really very powerful.

Tim

jkuipers · **Joined:** Thu Jun 02, 2005 5:09 am **Posts:** 22

It seems that none of the posters has found out how to properly configure WebSphere 5.x to use log4j for Commons Logging for just your application (and keep on using JRas for its own), so I'll give you the info:

Check out http://www-1.ibm.com/support/docview.wss?uid=swg27004610.

Since the follow-up link seems dead at the moment, I'll summarize briefly:
what you need to do is to create a file called META-INF/services/org.apache.commons.logging.LogFactory somewhere in your source directory with the following contents (just 1 line):

Code:

org.apache.commons.logging.impl.Log4jFactory

WebSphere 5.x uses Commons Logging 1.0, so commons-logging.properties won't do the trick. Using a system property as suggested will probably cause WebSphere to use log4j for its own logging as well, which is not what you want (haven't tried it, though). Using the jar services discovery mechanism does the trick here. IBM has documented this fix/workaround themselves, so I consider it supported, but it's kind a strange that the link on the page given above doesn't seem to exist anymore...

HTH.

Joris

jgodea · **Joined:** Thu Jun 15, 2006 2:15 pm **Posts:** 15

Sorry I am responding to this so late. I got sidetracked, you know how that goes.

Your solution worked!

Thank you!

DanielSerodio · **Posted:** Fri Jan 05, 2007 11:30 am

bill.horan wrote:

O frabjous day! Callooh! Callay!

I thought it might be a commons logging issue - but hadn't traced it down. Thanks for finding it/pointing it out!

In my searches, I saw various websites declaring the evil of commons logging and recommending the use of log4j directly.

Here were what I thought were good descriptions of some of the commons-logging issues in general:

http://www.qos.ch/logging/classloader.jsp
http://www.qos.ch/logging/thinkAgain.jsp - this one also has links to other articles supporting the removal of commons-logging from the face of the earth

Written as they were by the author of log4j I'm sure those two articles have no bias. (OK - so those articles may be biased - but after reading them I think they were fair and I'm convinced to stay far away from commons-logging.)

If any of the Hibernate core team are reading this - I (humbly) request two things:

1 (reasonable request) - on the Hibernate FAQ about how to configure log4j logging for Hibernate, please add a link to the WebSphere/Common-Logging issue pointed out by Curtis http://jakarta.apache.org/commons/logging/commons-logging-1.1/troubleshooting.html#Containers_With_Custom_LogFactory_Implementations

2 (unreasonable request - but I'm hoping anyway) - please drop the commons-logging API entirely and switch to log4j directly (or to the replacement for log4j when it arrives). I despair trying to count the wasted hours myself and other developers on this project wrestled with the log4j and hibernate configurations trying to coax the desired debug messages to appear - when the whole time it was a WebSphere/commons-logging collision causing the problem.

Thanks again Curtis!

Yes, commons-logging is the devil! :-) It causes problems when reloading applications in Tomcat, it behaves differently in development, testing and production, it causes "missing log" problems and doesn't solve any pre-existing problem.
If only Sun had adopted log4j instead of reinventing the wheel, commons-logging wouldn't even exist.