Hibernate et Log4j

Version imprimable

Hibernate et Log4j

Bonjour tout le monde.

J'ai un petit soucis et je fais appel à vous avant qu'il ne me reste plus aucun cheveux sur la tête.

J'ai un bête petit projet java qui fait de la persistence.
Donc une entité (@entity), un fichier persistence.xml (avec connection vers une db db2) et une classe de test. Tout fonctionne très bien sauf pour le log.

J'ai simplement ajouté un fichier log4j.properties :
Code:

1 2 3 4 5 6 7 8 9 10 11 # 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 # Root logger option log4j.rootLogger=error, stdout # Hibernate logging options log4j.logger.org.hibernate.SQL=debug #log4j.logger.org.hibernate=trace log4j.logger.org.hibernate.type=trace
Si je travaille avec les librairies de jboss 4.2, ça marche et j'ai :
Code:

1 2 3 4 5 6 7 8 09:43:33,737 DEBUG SQL:401 - select ... where school0_.O_I_ID=? 09:43:33,737 TRACE IntegerType:133 - binding '1' to parameter: 1 09:43:33,737 TRACE StringType:172 - returning 'x' as column: T2_0_0_ 09:43:33,747 TRACE StringType:172 - returning 'x' as column: T3_0_0_ 09:43:33,747 TRACE StringType:172 - returning 'x' as column: T4_0_0_ 09:43:33,757 TRACE IntegerType:172 - returning 'x' as column: N5_0_0_ 09:43:33,757 TRACE StringType:172 - returning 'x' as column: T6_0_0_ 09:43:33,757 TRACE StringType:172 - returning '' as column: T7_0_0_
Par contre avec jboss 4.0.5GA (et je dois utiliser celui-là) j'ai juste

Code:

09:43:33,737 DEBUG SQL:401 - select ... where school0_.O_I_ID=?

D'où ma question : comment faire pour avoir les 'bindings' avec jboss 4.0.5GA.
J'ai déjà essayé tout un tas de combinaisons debug,trace,info mais rien ne marche.

Merci.

11/12/2008, 10h30
sewatech

JBoss 4.0 utilise une version trop ancienne de Log4J, qui n'incluait pas encore le niveau Trace. Donc ta configuration ne changera rien à l'affaire. Pour résoudre le problème, il faudrait que tu utilises une version récente de log4j, directement dans ton application, avec une configuration propre à l'application.

Alexis

Salut Alexis.

Merci pour cette réponse (je m'en doutais un peu).
Parc contre, je ne comprends pas bien ce que tu propose. Et oui, désolé, mais je débute dans le domaine.

En fait, mon code est tout simple :

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
package client;
 
import javax.persistence.EntityManager;
import javax.persistence.EntityManagerFactory;
import javax.persistence.Persistence;
 
import entities.School;
 
public class Test1 
{
  public static void main(String[] args) 
    {
    EntityManagerFactory factory = Persistence.createEntityManagerFactory("entities");
    EntityManager        manager = factory.createEntityManager();
    School sc = manager.find(School.class,1);
    System.out.println(sc.getName());
    manager.close();
	  factory.close();
	  }
}

Que faut-il ajouter ?

Merci.

11/12/2008, 11h22
sewatech

Il n'y a rien à changer dans ton code, c'est un problème de librairies présentes dans ton classpath (ou buildpath, si tu es dans eclipse). Il faut que log4j y soit déclaré afin que ton application puisse l'utiliser.

Si tu veux plus de détails, il faudrait que tu précise ton environnement de travail (IDE, config du projet).

Alexis

Merci Alexis.

Grâce à tes explication ça marche.

En fait je travaille sous eclipse. Pour avoir plus facile, je me suis créé une 'user library' avec toutes les librairies de jboss 4.0.5 sauf log4j que je prends dans la 4.2.

Par contre, encore une petite question.

Voici mon fichier persistence.xml
Code:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 <?xml version="1.0" encoding="UTF-8"?> <persistence> <persistence-unit name="entities" transaction-type="RESOURCE_LOCAL"> <properties> <property name="hibernate.dialect" value="org.hibernate.dialect.DB2Dialect"/> <property name="hibernate.connection.driver_class" value="com.ibm.db2.jcc.DB2Driver"/> <property name="hibernate.connection.url" value="jdbc:db2://..."/> <property name="hibernate.connection.username" value="..."/> <property name="hibernate.connection.password" value="..."/> <property name="hibernate.default_schema" value="..." /> <property name="hibernate.show_sql" value="true"/> <property name="hibernate.format_sql" value="false"/> <property name="use_sql_comments" value="true"/> </properties> </persistence-unit> </persistence>
avec <property name="hibernate.show_sql" value="true"/> j'ai :

Code:

Hibernate: select ... where school0_.O_I_ID=?

Et là rien d'autre. Que ce soit avec jboss 4.0.5 ou 4.2.
Comme le persistence est gérée par un ejb ça me serait utile d'avoir ces infos sur la console du serveur.

Tu as une idée ?

Bon alors je progresse ...

En modifiant le fichier log4j.xml du server (dans server/xxx/conf).
Et en faisant passer le parametre 'Threshold' de l'appender console à 'DEBUG', j'ai plus d'informations.

Code:

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
30
31
2008-12-11 14:21:11,690 DEBUG [ServerThread] WAKEUP in SERVER THREAD
2008-12-11 14:21:11,690 DEBUG [ServerThread] beginning dorun
2008-12-11 14:21:11,710 DEBUG [SessionImpl] opened session at timestamp: 5033990847324160
2008-12-11 14:21:11,710 DEBUG [AbstractEntityManagerImpl] Looking for a JTA transaction to join
2008-12-11 14:21:11,710 DEBUG [JDBCContext] successfully registered Synchronization
2008-12-11 14:21:11,710 DEBUG [AbstractEntityManagerImpl] Looking for a JTA transaction to join
2008-12-11 14:21:11,710 DEBUG [AbstractEntityManagerImpl] Transaction already joined
2008-12-11 14:21:11,710 DEBUG [Loader] loading entity: [entities.School#1]
2008-12-11 14:21:11,710 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-12-11 14:21:11,710 DEBUG [ConnectionManager] opening JDBC connection
2008-12-11 14:21:11,710 DEBUG [SQL] select ... where school0_.O_I_ID=?
2008-12-11 14:21:11,710 INFO  [STDOUT] Hibernate: select ... where school0_.O_I_ID=?
2008-12-11 14:21:11,740 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2008-12-11 14:21:11,740 DEBUG [Loader] result row: EntityKey[entities.School#1]
2008-12-11 14:21:11,740 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2008-12-11 14:21:11,740 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2008-12-11 14:21:11,740 DEBUG [ConnectionManager] aggressively releasing JDBC connection
2008-12-11 14:21:11,740 DEBUG [ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2008-12-11 14:21:11,740 DEBUG [TwoPhaseLoad] resolving associations for [entities.School#1]
2008-12-11 14:21:11,740 DEBUG [TwoPhaseLoad] done materializing entity [entities.School#1]
2008-12-11 14:21:11,740 DEBUG [StatefulPersistenceContext] initializing non-lazy collections
2008-12-11 14:21:11,740 DEBUG [Loader] done entity load
2008-12-11 14:21:11,740 DEBUG [AbstractFlushingEventListener] processing flush-time cascades
2008-12-11 14:21:11,740 DEBUG [AbstractFlushingEventListener] dirty checking collections
2008-12-11 14:21:11,740 DEBUG [AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2008-12-11 14:21:11,740 DEBUG [AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2008-12-11 14:21:11,740 DEBUG [Printer] listing entities:
2008-12-11 14:21:11,740 DEBUG [Printer] entities.School{id=1, zip=x, address=x, name=x, remarks=, country=x, city=x}
2008-12-11 14:21:11,740 DEBUG [ConnectionManager] aggressively releasing JDBC connection
2008-12-11 14:21:11,750 DEBUG [ManagedEntityManagerFactory] ************** closing entity managersession **************
2008-12-11 14:21:11,780 DEBUG [ServerThread] begin thread wait

La ligne [Printer] entities.School{id=1, zip=x, address=x, name=x, remarks=, country=x, city=x}
est très intéressante. Par contre pas de trace de ce qui est mis à la place du ? dans la requête.

Au fait c'est possible de dire que pour le niveau debug je ne veux que ce qui est 'printer' ?

11/12/2008, 14h31
sewatech

Comment déploies-tu ton EJB, dans JBoss ? Sous la forme d'un jar autonome ou dans un ear ?

Si c'est un jar autonome, tu pourras bien y mettre ton fichier log4j.properties, mais tu devras forcément utiliser le log4j de JBoss.
Si c'est un ear, tu peux y mettre le log4j.jar de ton choix.

Avant de compléter mes explications, précise moi dans que cas tu es.

Alexis
11/12/2008, 14h33
tweetysat

Je déploie un jar.
11/12/2008, 14h48
sewatech

Dans ce cas, tu n'as aucune possibilité pour avoir le niveau trace avec JBoss 4.0. Le mieux est de faire ta configuration log4j dans le fichier conf/log4J.xml (pour JBoss 4.0) ou conf/jboss-log4j.xml (pour JBoss 4.2).

Les traces de hibernate.show_sql sortent en catégorie [STDOUT], avec le niveau info. Elles ne sont pas règlables.

Alexis
11/12/2008, 15h04
tweetysat

Ok, merci.

Mais je suppose que ce que tu me propose est ce que je fais quelques posts plus haut (14h27) et qu'il n'y a rien d'autre à faire ?
11/12/2008, 16h01
sewatech

Oups, je n'avais pas lu ce message...

Pour activer le debug pour Printer, il faut que tu laisse la catégorie root en INFO et que tu déclares une nouvelle catégorie pour Printer (avec son package) en niveau DEBUG. Mais pour ça, je crois qu'il y a plusieurs articles intéressants sur le site...

Alexis
11/12/2008, 16h04
tweetysat

Ok merci pour ton aide, j'examine ça demain.