Como loggear el SQL que genera Hibernate con los parámetros de la consulta

Hace poco me vi en la necesidad de analizar los queries que genera Hibernate, pero la información que estaba necesitando era relacionada a los valores de los parámetros que recibía mi query.

Hibernate posee un par de opciones bastante conocidas para mostrar el SQL generado, una es agregar el parámetro "hibernate.show_sql" con valor true, en la configuración del SessionFactory. Como acotación al margen, existen otros dos parámetros interesantes: "hibernate.format_sql", el cual si el valor es verdadero, formatea la sentencia SQL generada (útil cuando analizamos consultas complejas), y la otra es "hibernate.use_sql_comments", que cuando tiene el valor verdadero agrega a las sentencias, comentarios relevantes (ej.: se está persistiendo la clase com.xxxx.yyyy.ClaseZZZ). Este enfoque tiene la contra de que se usa la salida estándard (no es compatible con frameworks de logging como log4j) y además no muestra los parámetros utilizados para ejecutar la consulta.

Otra opción es configurar el output mediante log4j. En este caso es necesario activar el logger "org.hibernate.SQL". Luego de hacerlo, hibernate comenzará a mostrar las líneas por nuestros appenders configurados, lo cual es mejor que el escenario anterior, pero sigue sin mostrar los parámetros. Sin embargo existe otro logger, el cual si permite mostrar esta información: "org.hibernate.type". El problema es que si tenemos varios parámetros, los va a mostrar en muchas líneas:

Hibernate: INSERT INTO transactions (CHANGE, CLOSE, DATE, OPEN, CURRENT_ID, VOLUME) 
VALUES (?, ?, ?, ?, ?, ?)
15:33:07,243 DEBUG FloatType:133 - binding '10.0' to parameter: 1
15:33:07,243 DEBUG FloatType:133 - binding '1.2' to parameter: 2
15:33:07,243 DEBUG DateType:133 - binding '30 December 2009' to parameter: 3
15:33:07,259 DEBUG FloatType:133 - binding '1.4' to parameter: 4
15:33:07,259 DEBUG IntegerType:133 - binding '12' to parameter: 5
15:33:07,259 DEBUG LongType:133 - binding '344444' to parameter: 6

Por lo tanto me dispuse a buscar otra solución, que de paso me sirviera para mostrar todas las sentencias SQL que se vayan generando, incluso, porque no, otras que no provengan de Hibernate mismo.
Me encontré con el proyecto Log4JDBC, el cual era más o menos lo que estaba necesitando. Luego de analizarlo me encontré con el problema de que no funciona muy bien con aplicaciones que usan pooles de conexiones provistos por el application server (en mi caso Tomcat), y era complicado de configurar para que funcione correctamente.
Continuando la búsqueda me encontré con un fork: Log4JDBCRemix, que si bien, advierten de ser bastante experimental, funciona de maravillas. La diferencia con Log4JDBC original, es que es más amigable a Maven, y además más simple de configurar, porque funciona como un wrapper de un datasource.
A grandes rasgos, para hacerlo andar es necesario hacer lo siguiente:

1) Agregar la dependencia Maven:

<dependency>
  <groupId>org.lazyluke</groupId>
  <artifactId>log4jdbc-remix</artifactId>
  <version>0.2.7</version>
</dependency>

2) Si se usa spring, agregar un bean que funcione como indirección al verdadero datasource:

  <bean id="dataSourceSpied" class="...">
    <property name="driverClass" value="${datasource.driverClassName}"/>
    <property name="jdbcUrl" value="${datasource.url}"/>
    <property name="user" value="${datasource.username}"/>
    <property name="password" value="${datasource.password}"/>
    ...
  </bean>

  <bean id="dataSource" class="net.sf.log4jdbc.Log4jdbcProxyDataSource">
    <constructor-arg ref="dataSourceSpied" />
  </bean>

3) Configurar que mostrar finalmente en el log (en mi caso, solo necesitaba la sentencia con los parámetros reemplazados):

log4j.logger.jdbc.audit=FATAL
log4j.logger.jdbc.resultset=FATAL
log4j.logger.jdbc.resultsettable=FATAL
log4j.logger.jdbc.sqlonly=DEBUG
log4j.logger.jdbc.sqltiming=FATAL
log4j.logger.jdbc.connection=FATAL

Al momento de usar el aplicativo, vamos a poder ver en nuestro archivo de log, todas las sentencias SQL logueadas con los parámetros correspondientes, reemplazados en la misma línea:

29.07.2013 23:49:05 DEBUG (Slf4jSpyLogDelegator.java:232) -  org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
5. select groups0_.id_user as id2_3_1_, groups0_.id_group as id1_1_, group1_.id_group as id1_1_0_, 
group1_.creation_date as creation2_1_0_, group1_.last_modification_date as last3_1_0_, group1_.creation_user 
as creation4_1_0_, group1_.last_modification_user as last5_1_0_, group1_.name as name1_0_ from 
public.groups_users groups0_ inner join groups group1_ on groups0_.id_group=group1_.id_group 
where groups0_.id_user=45 
29.07.2013 23:49:06 DEBUG (Slf4jSpyLogDelegator.java:232) -  org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
6. select roles0_.id_group as id1_1_1_, roles0_.id_role as id2_1_, role1_.id_role as id1_2_0_, 
role1_.creation_date as creation2_2_0_, role1_.last_modification_date as last3_2_0_, role1_.creation_user 
as creation4_2_0_, role1_.last_modification_user as last5_2_0_, role1_.name as name2_0_, role1_.id_super_role 
as id7_2_0_ from public.groups_roles roles0_ inner join roles role1_ on roles0_.id_role=role1_.id_role 
where roles0_.id_group=44 

Luego de usarlo, me enteré de que existe un nuevo proyecto, denominado log4jdbc-log4j2, que posee todas las mejoras de Log4JDBCRemix, y algunas más.

Mapeos más dinámicos: Fluent NHibernate

Como muchos saben, la herramienta de ORM más conocida en el mundo JAVA, Hibernate, tiene su port, bastante actualizado por cierto, en el mundo .NET. Hace poco tuvimos que empezar un proyecto en esta plataforma, y un integrante del equipo, sugirió utilizar Fluent NHibernate. Se trata básicamente de una librería, con un enfoque “fluent” para construir los mappings de las entidades.

Al principio pensé que quizá no era una buena idea utilizar otra manera de hacer mapeos, ya que si teníamos algún problema quizá iba a ser un poco más difícil pedir soporte a otros equipos que tenían más experiencia, pero igualmente decidimos ir para adelante, por lo menos inicialmente, para probar que tan difícil era armarlos.

Por suerte para crear los primeros mapeos pudimos utilizar una herramienta generadora de código, que tenía soporte para crear los mapeos con Fluent. Igualmente fue necesario retocar lo generado, como siempre suele suceder con este tipo de herramientas.

Luego de un tiempo, al final creo que fue una buena idea, y se me ocurrió buscar si había algo parecido en el mundo JAVA, y lamentablemente no pude encontrar nada similar.

La idea básica de este framework es tener una clase con código fuente (en este caso c#) que define el mapeo. Ejemplo:

1:  public class CatMap : ClassMap<Cat>  
2:  {  
3:   public CatMap()  
4:   {  
5:    Id(x => x.Id);  
6:    Map(x => x.Name)  
7:     .Length(16)  
8:     .Not.Nullable();  
9:    Map(x => x.Sex);  
10:    References(x => x.Mate);  
11:    HasMany(x => x.Kittens);  
12:   }  
13:  }  

Lo bueno de este enfoque, comparado con archivos XML, es que muchas cosas se resuelven en tiempo de compilación. La otra ventaja, es que utilizando el Intellisense de la IDE (VisualStudio en este caso), podemos tener rápidamente un vistazo de los diferentes atributos de cada parte del mapeo que estamos construyendo, y contextualizados al campo que estamos mapeando.El startup time, además, es bastante bueno y rápido. 

En fin, esto demuestra que las buenas ideas, traspasan todas las plataformas, y así como .NET se vió beneficiado con el port de uno de los mejores frameworks de persistencia, JAVA podría verse beneficiado con otra forma interesante de construir mapeos si alguien se anima a hacer un port de esta librería en el mundo JAVA :)