Hibernate + Log4j

[Chtonian]

Guten Tag, ich habe eine Frage zu Hibernate, JPA, Log4j und Jboss 4.2.3 GA

Wir haben das Problem, dass die Ausgaben von Hibernate nicht über Log4j ausgegeben werden, sondern über STDERR in der Konsole / Logfile von JBoss landen.

Die Ausgabe von Hibernate sieht so aus:

12:01:33,836 ERROR [STDERR] 26.06.2009 12:01:33 org.hibernate.tool.hbm2ddl.SchemaUpdate execute
SCHWERWIEGEND: Table 't_word' already exists

12:01:22,759 ERROR [STDERR] 26.06.2009 12:01:22 org.hibernate.cfg.annotations.Version <clinit>
INFO: Hibernate Annotations 3.4.0.GA

Die Log4J Config XML im %JBOSS_HOME%/server/default/conf Ordner sieht so aus:

[XML]
<appender name="HIBERNATE" class="org.apache.log4j.ConsoleAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
<param name="Target" value="System.out"/>
<param name="Threshold" value="TRACE"/>

<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
</layout>
</appender>
<category name="org.hibernate">
<priority value="TRACE"/>
<appender-ref ref="HIBERNATE"/>
</category>

<category name="org.hibernate.util.JDBCExceptionReporter">
<priority value="FATAL"/>
<appender-ref ref="HIBERNATE"/>
</category>

<category name="org.hibernate.hql.ast.QueryTranslatorImpl">
<priority value="ERROR"/>
<appender-ref ref="HIBERNATE"/>
</category>
[/XML]

Anscheinend ignoriert Hibernate / JPA diese Konfiguration, denn für alle anderen eigenen Logger funktioniert diese Konfigurations datei.

Gibt es eine Möglichkeit, Log4j für Hibernate zu aktivieren, oder ist es ein generelles JBoss Problem ?

 

[Fenixx]

Hi,

Log4J kann man natürlich für Hibernate verwenden. Wie die Einstellungen im JBoss konkret aussehen weiß ich leider nicht.
Verwendest du denn auch den Logger von log4j für die Logausgaben? Das müsste in etwa so aussehen:

private Logger log = Logger.getLogger(this.getClass());
//Die Logausgabe
log.info("Meine Logausgabe");

Gruß

 

[Chtonian]

Vielen Dank für deine Antwort!

Wir verwenden Log4j für alle anderen Ausgaben innerhalb des Serverkontextes und bei jedem anderen Element funktioniert das. Nur die Hibernatespezifischen Sachen werden nicht über log4j sondern über STDERR ausgegeben.

 

[Fenixx]

Hi,

aufgrund deines Beitrags kann zwar nicht eindeutig schließen, ob deine Frage beantwortet ist.
Deswegen hier ein Auszug aus der log4j.xml, was dich interessieren könnte. Die Konfiguration ist allerdings für den Glassfish. Sollte an sich aber keine Probleme mit dem JBoss geben:

<?xml version="1.0" encoding="UTF-8"?><!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">

    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
        <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
        <param name="Target" value="System.out"/>
        <layout class="org.apache.log4j.PatternLayout">
            <!-- The default pattern: Date Priority [Category] Message\n -->
            <param name="ConversionPattern" value="%-5p [%c{6}] %m%n"/>
        </layout>
    </appender>

    <!-- ############### Hibernate logging ################# -->

    <category name="org.hibernate">
        <priority value="TRACE"/>
    </category>

    <!--
    <category name="org.hibernate.SQL">
        <priority value="TRACE"/>
    </category>
    <category name="org.hibernate.type">
        <priority value="TRACE"/>
    </category>
    <category name="org.hibernate.loader">
        <priority value="TRACE"/>
    </category>
    <category name="org.hibernate.cache">
        <priority value="TRACE"/>
    </category>
    -->

    <root>
        <priority value="INFO"/>
        <appender-ref ref="CONSOLE"/>
    </root>

</log4j:configuration>

Gruß

 

[Chtonian]

So ich habe unsere jboss-log4j.xml angepasst, und nachwievor erscheinen die ausgaben von Hibernate nicht über das logging System sondern so:

ERROR [STDERR] 02.07.2009 10:30:38 org.hibernate.tool.hbm2ddl.SchemaUpdate execute
SCHWERWIEGEND: Unsuccessful: create table b2w_mining.t_ID_GEN ( ID_NAME varchar(255),  ID_VAL integer ) 
ERROR [STDERR] 02.07.2009 10:30:38 org.hibernate.tool.hbm2ddl.SchemaUpdate execute
SCHWERWIEGEND: Table 't_id_gen' already exists
ERROR [STDERR] 02.07.2009 10:30:38 org.hibernate.tool.hbm2ddl.SchemaUpdate execute
INFO: schema update complete
ERROR [STDERR] 02.07.2009 10:30:38 org.hibernate.util.NamingHelper getInitialContext
INFO: JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}

Ein normaler Eintrag hingegen sieht so aus:

INFO  [org.jboss.ejb3.JmxKernelAbstraction] creating wrapper delegate for: org.jboss.ejb3.stateless.StatelessContainer
INFO  [org.jboss.ejb3.JmxKernelAbstraction] installing MBean: jboss.j2ee:ear=B2W.ear,jar=Persistence.jar,name=DataHandler,service=EJB3 with dependencies:
INFO  [org.jboss.ejb3.JmxKernelAbstraction] 	persistence.units:ear=B2W.ear,jar=Persistence.jar,unitName=Persistence

 

[kama]

Hallo,

<appender name="HIBERNATE" class="org.apache.log4j.ConsoleAppender">
      <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
      <param name="Target" value="System.out"/>
      <param name="Threshold" value="TRACE"/>
 
      <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
      </layout>
    </appender>
...
<category name="org.hibernate">  
      <priority value="TRACE"/>   
      <appender-ref ref="HIBERNATE"/>
    </category>

Und es wundert Dich nun, dass Ausgaben auf der Console sprich System.out kommen ? Hm...Da solltest Du nochmal einen Blick in die Log4j Configuration werfen....

MfG
Karl Heinz Marbaise

 

[Chtonian]

Na, ich glaube ich kann mich nich ganz deutlich ausdrücken

_Natürlich_ sollen die Einträge des Loggers auf System.out kommen, sonst müsste ich dauernd ein Logfile bemühen.

Was mich wundert, und was anscheinend hier niemanden auffällt, ist die Tatsache, dass die Einträge von Hibernate 1. nicht über den Logfile Parser geschickt werden, d.h. sie sind z.b. OHNE Timestamp, und dass sie über STDERR laufen, UND Danach nochmals als INFO, ERROR oder WARN ausgegeben werden.

Ich kopiere nochmals die betreffenden Einträge:

Hibernate:

ERROR [STDERR] 02.07.2009 10:30:38 org.hibernate.tool.hbm2ddl.SchemaUpdate execute
SCHWERWIEGEND: Unsuccessful: create table b2w_mining.t_ID_GEN ( ID_NAME varchar(255),  ID_VAL integer ) 
ERROR [STDERR] 02.07.2009 10:30:38 org.hibernate.tool.hbm2ddl.SchemaUpdate execute
SCHWERWIEGEND: Table 't_id_gen' already exists
ERROR [STDERR] 02.07.2009 10:30:38 org.hibernate.tool.hbm2ddl.SchemaUpdate execute
INFO: schema update complete

Normale JBoss ausgabe im System.out

11:39:28,768 INFO  [ExtendedDataHandler]  **** Statistics ****
11:39:28,768 INFO  [ExtendedDataHandler] Collection count: 0
11:39:28,768 INFO  [ExtendedDataHandler] Collection keys: {}
11:39:28,768 INFO  [ExtendedDataHandler] Entity count: 0
11:39:28,768 INFO  [ExtendedDataHandler] Entity keys: {}
11:39:28,768 INFO  [ExtendedDataHandler] Duration for <todotiny> 0 ms
11:39:28,768 INFO  [AbstractBaliWorker] Generation Time: 16 ms

Wie man hier erkennen kann, befolgt die logging ausgabe unseres ExtendedDataHandlers genau den Anweisungen aus der log4j.xml:

[XML]
<appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
<param name="Target" value="System.out"/>
<param name="Threshold" value="INFO"/>

<layout class="org.apache.log4j.PatternLayout">
<!-- The default pattern: Date Priority [Category] Message\n -->
<param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
</layout>
</appender>
[/XML]

Hibernate hingegen schickt seine Ausgaben über STDERR und danach als entsprechend dem Level des Logeintrags ins System.out

ERROR [STDERR] 02.07.2009 10:30:38 org.hibernate.tool.hbm2ddl.SchemaUpdate execute
INFO: schema update complete

Also: ERROR [STDERR] .... und dann dadrunter: INFO: schema update complete

Ich hätte gerne folgende ausgabe: (den oberen Hibernate code korrekt formatiert):

02.07.2009 10:30:38 SCHWERWIEGEND [SchemaUpdate] Unsuccessful: create table b2w_mining.t_ID_GEN ( ID_NAME varchar(255),  ID_VAL integer ) 
02.07.2009 10:30:38 SCHWERWIEGEND [SchemaUpdate] execute Table 't_id_gen' already exists
02.07.2009 10:30:38 INFO [SchemaUpdate] schema update complete

Ich möchte 1. die gesamten STDERR einträge nicht haben, und 2. das Format sollte dem der log4j entsprechen.

Ich hoffe jetzt ist klar, was ich meine

 

[akkie]

Hi

konntest du das Problem beheben? Bei mir tritt das gleiche Phänomen mit ActiveMQ auf. Exceptions werden einfach nicht mit Log4J geloggt. Alle anderen Levels schon.

Im Eclipse-Log steht dann:

25.11.2009 14:30:47 org.apache.activemq.ActiveMQMessageConsumer dispatch
SCHWERWIEGEND: ID:ws2-3008-1259155837227-2:0:1:1 Exception while processing message: java.lang.RuntimeException: test

Mfg Akkie

 

[dboeckli]

Hibernate benötigt ab 3.3 slf4j. Bei JBoss können die slf4j jar files aus dem JBoss Server 5.1 geholt werden oder via Maven mit folgender dependency Definition:
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>1.5.6</version>
<scope>provided</scope>
</dependency>
<dependency>
<groupId>org.jboss.slf4j</groupId>
<artifactId>slf4j-jboss-logging</artifactId>
<version>1.0.2.GA</version>
<scope>provided</scope>
</dependency>

Ich hoffe das wird weiterhelfen.

Dominique

 

[computersport]

Ist zwar schon etwas alt der Beitrag aber vielleicht Stolpert ja nochmal einer über dieses Problem.

Das Problem hatte ich auch.

guck in deine persistence.XML und schalt dort das Logging von Hibernate aus.