Java Ninja Chronicles By Norris Shelton

Things I learned in the pursuit of code

In a previous logback blog entry Hibernate Logging (e.g. JBOSS logging) I showed how to send the JBoss logging to your logback logging configuration.

One thing kept bothering me. If you turned on showSql, these were not captured by your logging. I was fishing through the code and discovered why. If you turn on showSql, it actually sets a variable named logToStdout. Just as the name says, in the code, it logs to STDOUT.

if ( logToStdout ) {
	System.out.println( "Hibernate: " + statement );

This results in logging like the following:

Hibernate: insert into cam_affiliate (Channel_ID, Name, Affiliate_ID) values (?, ?, ?)

Logging Sql statements via Logback

A better way is to NOT set showSql to true, but to add the following logger to your Logback configuration.

<!-- Displays the Hibernate SQL statements in your log instead of STDOUT like showSql does-->
<logger name="org.hibernate.SQL" level="DEBUG"/>

This displays logging similar to:

2016-02-19 09:09:30|DEBUG|insert into cam_affiliate (Channel_ID, Name, Affiliate_ID) values (?, ?, ?) ||org.hibernate.engine.jdbc.spi.SqlStatementLogger:92 

February 19th, 2016

Posted In: hibernate, hibernate logging, Java, java ninja, Javaninja, jboss logging, jcl-over-slf4j, log4j-over-slf4j, logback, Logging, Logging configuration, slf4j

Leave a Comment

I was getting the following debug logging, even though my logging config said info and above.

15:14:02.541|DEBUG|RdbmsOperation with SQL [p_select_validate_pin_person_token] compiled||org.springframework.jdbc.object.RdbmsOperation:344
15:14:02.541|DEBUG|Compiled stored procedure. Call string is [{call p_select_validate_sso_person_token(?, ?)}]||org.springframework.jdbc.object.SqlCall:154
15:14:02.541|DEBUG|RdbmsOperation with SQL [p_select_validate_sso_person_token] compiled||org.springframework.jdbc.object.RdbmsOperation:344
15:14:02.542|DEBUG|Compiled stored procedure. Call string is [{call p_delete_truncate(?)}]||org.springframework.jdbc.object.SqlCall:154
15:14:02.542|DEBUG|RdbmsOperation with SQL [p_delete_truncate] compiled||org.springframework.jdbc.object.RdbmsOperation:344
15:14:02.543|DEBUG|Compiled stored procedure. Call string is [{call p_update_setting_inprogress(?)}]||org.springframework.jdbc.object.SqlCall:154

During my research, I learned that Hibernate is logged via JBoss Logging. It used to require a properties file that denoted which logging implementation to use. It now will try to use several logging frameworks, such as commons-logging, log4j and logback. I use Logback.

One common problem is that if you are pulling in lots of dependent libraries, it isn’t uncommon to have multiple logging APIs preset. That was the case that I had.

I checked my dependencies and discovered that I had libraries for:

  • logback-classic – logback is my preferred logging framework.
  • commons-logging – this is the culprit. The JBoss logging API is finding this framework, but isn’t finding a configuration file so everything is being logged.
  • jboss-logging – this is the jboss logging api and is required
  • log4j-over-slf4j – this is the slf4j implementation of the log4j api. In essence, hijacking log4j and funnelling the log4j logging events through slf4j.

To fix this, I had to find every Maven dependency that has a transitive dependency on commons-logging and exclude commons-logging. An example of something that had commons-logging as a transitive dependency was spring-webmvc. I modified the dependency by adding exclusions.


Once I removed all commons-logging transitive dependencies, I had to provide a suitable substitute. This is where another SLF4j dependency comes in handy. This is a SLF4J implementation of the commons-logging api which funnels all of the commons-logging events to my slf4J implementation.


December 30th, 2014

Posted In: hibernate, hibernate logging, java ninja, Javaninja, jboss, jboss logging, jcl-over-slf4j, log4j-over-slf4j, logback, Logging, slf4j

Tags: , , , , , , , , , ,


WP to LinkedIn Auto Publish Powered By :