7 Replies Latest reply on May 19, 2015 4:44 PM by jamezp

    Logging problem with JBoss EAP 6.3 and hibernate 4

    hubeaul

      Hello,

       

           I am currently developping a small webapplication wich i deploy on JBoss EAP 6.3.0.GA (version 7.4.0.Final-redhat-19).

           This application use hibernate as its JPA provider (hibernate version 4.2.14.SP1-redhat-1) and it also use an EJB between the webapp and the data layer).

           I have succesfully configured my application to log its processes through  log4j in a specific file.

           I have also succesfully configure hibernate to log the statement parameters to the same file.

       

           My problem is that the statements generated by hibernate are never log to the file i have call my DAO through the webapp and those statements are logged to the server.log file if a remotely call the business EJB through a main method.

           I need this logs because the log provided by the spy on the datasource is not suitable for my case (i must log the hibernate stuff on a application basis rather than for the whole server).

       

           Can you say me waht i have misconfigured in my application ?

           Here is a lnk to github whre my application is currenlt stored : lionelh/jboss-testing · GitHub

       

         Here is the content of the log4j.properties file deployed with my application :

          #

          # ROOT LOGGER

          #

          log4j.rootLogger=DEBUG

       

          log4j.appender.applog=org.apache.log4j.DailyRollingFileAppender

          log4j.appender.applog.File=../standalone/log/jbosstesting.log

          log4j.appender.applog.DatePattern='-'yyyy-MM-dd

          log4j.appender.applog.layout=org.apache.log4j.PatternLayout

          log4j.appender.applog.layout.ConversionPattern=%5p *** %d{dd/MM/yyyy HH:mm:ss,SSS} *** (%C:%L) *** %m%n

       

          #

          # LOGGERS

          #

          log4j.logger.be.lionelh.jbosstesting=DEBUG, applog

          log4j.logger.org.hibernate.SQL=DEBUG, applog

          log4j.logger.org.hibernate.type.descriptor.sql.BasicBinder=trace, applog

          log4j.logger.org.hibernate.type.descriptor.sql.BasicEXtractor=trace, applog

       

          Here is the log received during JUnit test (this logs are correct) :

          DEBUG *** 14/03/2015 16:30:36,996 *** [main] (UserDaoImpl.java:41) *** In findById

          DEBUG *** 14/03/2015 16:30:36,999 *** [main] (SqlStatementLogger.java:104)    *** select user0_.US_ID as US_ID1_0_0_, user0_.US_CREATION_DATE as US_CREAT2_0_0_, user0_.US_LANGUAGE as US_LANGU3_0_0_,  user0_.US_LAST_UPDATE_DATE as US_LAST_4_0_0_, user0_.US_LOGIN as US_LOGIN5_0_0_ from phone_user user0_ where user0_.US_ID=?

          TRACE *** 14/03/2015 16:30:37,003 *** [main] (BasicBinder.java:84) *** binding parameter [1] as [BIGINT] - 1

          TRACE *** 14/03/2015 16:30:37,005 *** [main] (BasicExtractor.java:74) *** Found [2015-02-14 21:22:55.0] as column [US_CREAT2_0_0_]

          TRACE *** 14/03/2015 16:30:37,005 *** [main] (BasicExtractor.java:74) *** Found [F] as column [US_LANGU3_0_0_]

          TRACE *** 14/03/2015 16:30:37,006 *** [main] (BasicExtractor.java:74) *** Found [2015-02-14 21:22:55.0] as column [US_LAST_4_0_0_]

          TRACE *** 14/03/2015 16:30:37,006 *** [main] (BasicExtractor.java:74) *** Found [lh] as column [US_LOGIN5_0_0_]

       

          Here is the log recevied with the deployed application in JBoss (as you can see the SQL statement are missing) :

          DEBUG *** 14/03/2015 19:54:30,827 *** (be.lionelh.jbosstesting.web.UserBean:69) *** In login()

          DEBUG *** 14/03/2015 19:54:30,923 *** (be.lionelh.jbosstesting.data.ejb.JBossTestingBean:35) *** In createUser(UserDto)

          DEBUG *** 14/03/2015 19:54:30,924 *** (be.lionelh.jbosstesting.data.domain.dao.impl.UserDaoImpl:28) *** In create(User)

          TRACE *** 14/03/2015 19:54:31,146 *** (org.hibernate.type.descriptor.sql.BasicBinder:84) *** binding parameter [1] as [TIMESTAMP] - Sat Mar 14 19:54:31 CET 2015

          TRACE *** 14/03/2015 19:54:31,161 *** (org.hibernate.type.descriptor.sql.BasicBinder:84) *** binding parameter [2] as [VARCHAR] - F

          TRACE *** 14/03/2015 19:54:31,164 *** (org.hibernate.type.descriptor.sql.BasicBinder:84) *** binding parameter [3] as [TIMESTAMP] - Sat Mar 14 19:54:31 CET 2015

          TRACE *** 14/03/2015 19:54:31,165 *** (org.hibernate.type.descriptor.sql.BasicBinder:84) *** binding parameter [4] as [VARCHAR] - vp

       

           Thank you for your help.

        • 1. Re: Logging problem with JBoss EAP 6.3 and hibernate 4
          cleber.barcelos.costa

          What I did was modify the jboss -deployment - structure.xml file , located in WEB- INF folder to ignore the loggin jboss and consider my settings , so no need to modify the standalone.xml .

           

          <jboss-deployment-structure>

            <ear-subdeployments-isolated>true</ear-subdeployments-isolated>

            <deployment>

            <exclusions>

            <module name="org.apache.log4j" />

            <module name="org.jboss.logging" />

            </exclusions>

            </deployment>

          </jboss-deployment-structure>

          • 2. Re: Logging problem with JBoss EAP 6.3 and hibernate 4
            hubeaul

            The idea was good but it is not the right solution. In fact, even with your configuration, i hav onyl the parameters en not the SQL statement in the log file.

             

            I think there is a "bug" in hibernate 4 when he is deployed in JBoss EAP 6.3 because only the SQL statement are not logged.

            i have also try the following configuration for hibernate

               log4j.logger.org.hibernate=TRACE, applog

            With the above configuration have i also only the SQL parameters and not the SQL statement or other things hibernate might log wich is also not correct i think.

            • 3. Re: Logging problem with JBoss EAP 6.3 and hibernate 4
              jamezp

              Hibernate and all server dependencies will be tied to the server log context. There's no way to configure Hibernate logging for a deployments log context.

              --

              James R. Perkins

              • 4. Re: Logging problem with JBoss EAP 6.3 and hibernate 4
                hubeaul

                But then can you say me why i have the parameters logged (by hibernate of course) and not the statement. And more if i completely configure the log in the standalone.xml for them to go to the server.log, then i have not the parameters but only the SQL statement.

                With the following configuration in standalone.xml, i have only the SQL Statements and never the parameters in the server.log file

                <subsystem xmlns="urn:jboss:domain:logging:1.4">

                <console-handler name="CONSOLE">

                <level name="INFO"/>

                <formatter>

                <named-formatter name="COLOR-PATTERN"/>

                </formatter>

                </console-handler>

                <periodic-rotating-file-handler name="FILE" autoflush="true">

                <formatter>

                <named-formatter name="PATTERN"/>

                </formatter>

                <file relative-to="jboss.server.log.dir" path="server.log"/>

                <suffix value=".yyyy-MM-dd"/>

                <append value="true"/>

                </periodic-rotating-file-handler>

                <logger category="com.arjuna">

                <level name="WARN"/>

                </logger>

                <logger category="org.apache.tomcat.util.modeler">

                <level name="WARN"/>

                </logger>

                <logger category="org.jboss.as.config">

                <level name="DEBUG"/>

                </logger>

                <logger category="sun.rmi">

                <level name="WARN"/>

                </logger>

                <logger category="jacorb">

                <level name="WARN"/>

                </logger>

                <logger category="jacorb.config">

                <level name="ERROR"/>

                </logger>

                <logger category="org.hibernate.SQL">

                <level name="DEBUG"/>

                </logger>

                <logger category="org.hibernate.type.descriptor.sql.BasicBinder">

                <level name="TRACE"/>

                </logger>

                <logger category="org.hibernate.type.descriptor.sql.BasicEXtractor">

                <level name="TRACE"/>

                </logger>

                <root-logger>

                <level name="INFO"/>

                <handlers>

                <handler name="CONSOLE"/>

                <handler name="FILE"/>

                </handlers>

                </root-logger>

                <formatter name="PATTERN">

                <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>

                </formatter>

                <formatter name="COLOR-PATTERN">

                <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>

                </formatter>

                <formatter name="applog-formatter">

                <pattern-formatter pattern="%5p *** %d{dd/MM/yyyy HH:mm:ss,SSS} *** (%C:%L) *** %m%n"/>

                </formatter>

                </subsystem>

                 

                For me the logging of Hibernate on JBoss EAP 6.X is a little bit confusing.

                • 5. Re: Logging problem with JBoss EAP 6.3 and hibernate 4
                  jamezp

                  Check the logger defined for org.hibernate.type.descriptor.sql.BasicEXtractor, notice the capital X. Also have a look at the documentation for Hibernate logging. I think you actually want org.hibernate.SQL and org.hibernate.type.


                  I'll try explain why it as to work like this. In the JBoss Log Manager there is a LogContext that holds the configuration for the context. The server and all the modules use the system (default) log context. When a deployment contains a logging configuration a new log context is created for that deployment and only loggers and handlers created on that deployment will use the newly created log context. Things like Hibernate can't use that log context as they're loaded from the same class loader for all deployments. This means static loggers, which is what Hibernate uses, would be configured based on which ever deployment hit that class first to cause the logger to instantiate.


                  Hopefully that makes sense


                  --

                  James R. Perkins

                  • 6. Re: Logging problem with JBoss EAP 6.3 and hibernate 4
                    hubeaul

                    Thank you for your explanation. It is now clearer for me.

                     

                    But it is a bit annoying taht hibernate logging is done on a server basis rather than per deployment. But we can do nothing against this behaviour.

                    • 7. Re: Logging problem with JBoss EAP 6.3 and hibernate 4
                      jamezp

                      It has to be though as it's a shared dependency. Otherwise if you deployed multiple applications then the first application that uses Hibernate would be the one that configures logging for Hibernate.

                       

                      --

                      James R. Perkins