Controlling Hibernate Output with Log4J

Our Simple Hibernate Application is a bit verbose. That’s probably okay for a web application because stdout actually ends up in a server log. But it’s a bit annoying in console application. Fortunately, Hibernate uses the Apache commons-logging abstraction layer and Hibernate logging is easily configured.

First, a quick aside on logging. Logging packages are a mechanism that allow a developer to add diagnostic messages to the code and specify the message level and destination at runtime. The design allows the developer to define a hierarchical logging structure in which each level inherits the properties of the level above it unless otherwise specified. Typically, the logging structure mirrors the package structure as that is both simple and effective. The JCL Users Guide is a good place to start for more information.

Apache commons-logging supports the log4j, JDK 1.4, and JCL SimpleLog Logging packages. We’ll use log4j because I’m already familiar with it and the Hibernate distribution includes a sample log4j.properties file.

Here are the required changes to our build.xml file (shown in bold). First, there is a new property that locates the log4j jar file. And second, the log4j jar file is added to the execution classpath.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
<project default="all">
<property name="HBM-HOME" location="/Projects/Java/hibernate" />
<property name="JDBC" location="/Projects/Server/hsqldb/lib/hsqldb.jar" />
<property name="LOG4J" location="/Projects/Java/Lib/log4j.jar" />

<property name="src-dir" location="src" />
<property name="cfg-dir" location="cfg" />
<property name="obj-dir" location="obj" />
<property name="TALK" value="false" />

<path id="classpath.base">
<pathelement location="${obj-dir}" />
<pathelement location="${HBM-HOME}/hibernate2.jar" />
<fileset dir="${HBM-HOME}/lib" includes="**/*.jar" />
<pathelement location="${JDBC}" />
</path>
<path id="classpath.run">
<pathelement location="${cfg-dir}" />
<path refid="classpath.base" />
<pathelement location="${LOG4J}" />
</path>

<target name="init">
<mkdir dir="${obj-dir}" />
</target>

...

</project>

And here is the log4j.properties file from my hibernate distribution.

  • The first block of parameters define an output channel identified as stdout. This channel directs messages to the standard output.
  • The second block of parameters define an output channel identified as file. This channel directs messages to the hibernate.log file.
  • The rootLogger assignment defines the default behavior as directing messages at or more severe than the warn level to the stdout channel.
  • And the remaining assignments change the output levels to info for the respective packages.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
### direct log messages to stdout ###
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

### direct messages to file hibernate.log ###
#log4j.appender.file=org.apache.log4j.FileAppender
#log4j.appender.file.File=hibernate.log
#log4j.appender.file.layout=org.apache.log4j.PatternLayout
#log4j.appender.file.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

### set log levels - for more verbose logging change 'info' to 'debug' ##

log4j.rootLogger=warn, stdout

log4j.logger.net.sf.hibernate=info

### enable the following line if you want to track down connection ###
### leakages when using DriverManagerConnectionProvider ###
#log4j.logger.net.sf.hibernate.connection.DriverManagerConnectionProvider=trace

### log JDBC bind parameters ###
log4j.logger.net.sf.hibernate.type=info

### log prepared statement cache activity ###
log4j.logger.net.sf.hibernate.ps.PreparedStatementCache=info

The easiest solution is to simply uncomment the lines defining the file channel and redefine the rootLogger to use the file channel. This will direct the log output to the hibernate.log file.

1
### direct log messages to stdout ###
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

### direct messages to file hibernate.log ###
log4j.appender.file=org.apache.log4j.FileAppender
log4j.appender.file.File=hibernate.log
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

### set log levels - for more verbose logging change 'info' to 'debug' ##

log4j.rootLogger=warn, file

log4j.logger.net.sf.hibernate=info

### enable the following line if you want to track down connection ###
### leakages when using DriverManagerConnectionProvider ###
#log4j.logger.net.sf.hibernate.connection.DriverManagerConnectionProvider=trace

### log JDBC bind parameters ###
log4j.logger.net.sf.hibernate.type=info

### log prepared statement cache activity ###
log4j.logger.net.sf.hibernate.ps.PreparedStatementCache=info

But here’s another option. We’ll create two properties files, one that directs the output to hibernate.log and another that directs the output to both System.out and hibernate.log. Then we’ll use the condition task and the java sysproperty task to specify the desired configuration file based upon the value of the TALK property.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
<project default="all">
< ... >

<target name="setup-run" depends="clean-run">
<condition property="LOG4J_OUT" value="log4j-to-stdout.properties">
<istrue value="${TALK}"/>
</condition>
<condition property="LOG4J_OUT" value="log4j-to-file.properties">
<isfalse value="${TALK}"/>
</condition>
</target>
<target name="run" depends="compile,setup-run">
<java classname="Main"
fork="true">

<classpath refid="classpath.run" />
<sysproperty key="log4j.configuration" value="${LOG4J_OUT}" />
</java>
</target>
<target name="clean-run">
<delete verbose="${TALK}" file="hibernate.log" />
</target>

< ... >
</project>

Now we can specify via the command line whether to view the logging messages on System.out or not.

1
$ ant run
Buildfile: build.xml

init:

compile:

clean-run:

setup-run:

run:

BUILD SUCCESSFUL
Total time: 12 seconds
$ wc -l hibernate.log 
      15 hibernate.log
$ ant -DTALK=true run
Buildfile: build.xml

init:

compile:

clean-run:
   [delete] Deleting: /Projects/Learn/Hibernate/Simple/hibernate.log

setup-run:

run:
     [java] 15:38:16,872  INFO Environment:401
                          - Hibernate 2.0.1
     [java] 15:38:16,898  INFO Environment:435
                          - loaded properties ... 
     [java] 15:38:16,942  INFO Environment:450
                          - using CGLIB reflection optimizer
     [java] 15:38:17,029  INFO Environment:460
                          - JVM proxy support: true
     [java] 15:38:17,080  INFO Configuration:283 
                         - Mapping resource: hb/Keyword.hbm.xml
     [java] 15:38:20,273  INFO Binder:176
                          - Mapping class: hb.Keyword -> keywords
     [java] 15:38:21,977  INFO SessionFactoryImpl:140
                               - building session factory
     [java] 15:38:22,114  INFO Dialect:37
                               - Using dialect: net.sf.hibernate.dialect.HSQLDialect
     [java] 15:38:22,167  INFO DriverManagerConnectionProvider:41
                               - Hibernate connection pool size: 2
     [java] 15:38:22,249  INFO DriverManagerConnectionProvider:70
                               - using driver: org.hsqldb.jdbcDriver
                                 at URL: jdbc:hsqldb:hsql:\//localhost
     [java] 15:38:22,259  INFO DriverManagerConnectionProvider:71
                               - connection properties: {user=user, password=user}
     [java] 15:38:22,260  INFO SessionFactoryImpl:170
                               - Use outer join fetching: false
     [java] 15:38:22,533  INFO SessionFactoryImpl:193
                               - Use scrollable result sets: true
     [java] 15:38:23,623  INFO SessionFactoryObjectFactory:82
                               - no JDNI name configured
     [java] 15:38:23,627  INFO SessionFactoryImpl:287
                               - Query language substitutions: {}

BUILD SUCCESSFUL
Total time: 13 seconds
$ wc -l hibernate.log 
      15 hibernate.log
$ exit

Our application still persists keyword objects without regard for existing keyword objects, but at least it does so quietly. If you’re following along, then here is the source for our Simple Hibernate application with log4j. We’ll fix the persistence problem next.

Disclaimer: I don’t claim to be an expert on hibernate. Please send comments and corrections.