12 Replies Latest reply on Aug 30, 2011 2:55 PM by Scott Marlow

    Hibernate' query logging doesn't work any more

    Juergen Zimmermann Master

      In the past I could set the log category "org.hibernate.SQL" to DEBUG and the generated SQL statements were logged in e.g. the log file. However, in the new JBoss builds (I tried build 1460) nothing is logged. I also tried org.hibernate.sql without success. Is this feature gone?

        • 2. Re: Hibernate' query logging doesn't work any more
          Are Tysnes Newbie

          Seting the log level to TRACE (to get everything) gave me this:

           

          14:51:17,571 DEBUG [org.hibernate.engine.jdbc.spi.SqlStatementLogger] (http--127.0.0.1-8080-6)

              select

          <snip.. our sql prettyprinted>

           

          14:51:17,571 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (http--127.0.0.1-8080-6) binding parameter [1] as [INTEGER] - 10000000

          14:51:17,571 TRACE [org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler] (http--127.0.0.1-8080-6) Handling invocation of statement method [setInt]

          14:51:17,571 TRACE [org.hibernate.engine.jdbc.internal.proxy.PreparedStatementProxyHandler] (http--127.0.0.1-8080-6) Binding via setInt: [1, 10000000]

           

          We use JPA 2 generated queries

          • 3. Re: Hibernate' query logging doesn't work any more
            Juergen Zimmermann Master

            Are, for which package resp. category are you setting the log level to TRACE?

            • 4. Re: Hibernate' query logging doesn't work any more
              Are Tysnes Newbie

              Sorry.. I should have mentioned that.. I was just playing with the root-logger to debug some strange as 7 behaviour when I noticed the hibernate trace/debug:

               

              JBoss Console

              - Core

              -- Logging

               

              root-logger -> Log level TRACE

               

              Click on the Handler tab

               

              File and/or Console handler -> Log level TRACE

               

              Just curious.. why don't you use the hibernate properties hibernate.show_sql and hibernate.format_sql in your persistence.xml ?

               

              <property name="hibernate.show_sql" value="true"/>

              <property name="hibernate.format_sql" value="true"/>

              • 5. Re: Hibernate' query logging doesn't work any more
                Juergen Zimmermann Master

                The property hibernate.show_sql just logs to the console, but not to server.log.

                • 6. Re: Hibernate' query logging doesn't work any more
                  Are Tysnes Newbie

                  Sounds strange.. the sql is showing up in both console and server.log in our JPA 2 project. Nothing fancy in the log4j.properties as I can tell which should force this. This was also default behaviour in AS 6 as far as I know.

                   

                  Let me know if you need to investigate any of the properties files in our project.

                  • 7. Re: Hibernate' query logging doesn't work any more
                    Juergen Zimmermann Master

                    Could you post the section <subsystem xmlns="urn:jboss:domain:logging:1.0"> inside standalone/configuration/standalone.xml , please?

                    • 8. Re: Hibernate' query logging doesn't work any more
                      Are Tysnes Newbie
                      standalone.xml

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

                                  <console-handler name="CONSOLE" autoflush="true">

                                      <level name="INFO"/>

                                      <formatter>

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

                                      </formatter>

                                  </console-handler>

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

                                      <level name="INFO"/>

                                      <formatter>

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

                                      </formatter>

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

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

                                  </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="sun.rmi">

                                      <level name="WARN"/>

                                  </logger>

                                  <root-logger>

                                      <level name="INFO"/>

                                      <handlers>

                                          <handler name="CONSOLE"/>

                                          <handler name="FILE"/>

                                      </handlers>

                                  </root-logger>

                              </subsystem>

                       

                      persistence.xml

                      <?xml version="1.0" encoding="UTF-8"?>

                      <persistence version="1.0"

                          xmlns="http://java.sun.com/xml/ns/persistence

                          xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

                          xsi:schemaLocation="http://java.sun.com/xml/ns/persistence

                              http://java.sun.com/xml/ns/persistence/persistence_1_0.xsd">

                          <persistence-unit name="MyAppEntityPU">

                              <provider>org.hibernate.ejb.HibernatePersistence</provider>

                              <jta-data-source>java:jboss/datasources/MySqlMyAppDS</jta-data-source>

                       

                              <class>my-app.entity.CategoryEntity</class>

                              <class>my-app.entity.ChannelEntity</class>

                       

                              <properties>

                                  <property name="openjpa.jdbc.DBDictionary" value="org.apache.openjpa.jdbc.sql.MySQLDictionary" />

                                  <property name="jboss.entity.manager.jndi.name" value="java:/MyAppEntity"/>

                                  <property name="jboss.entity.manager.factory.jndi.name" value="java:/MyAppFactory"/>

                                  <property name="hibernate.show_sql" value="true"/>

                                  <property name="hibernate.format_sql" value="true"/>

                                  <property name="hibernate.max_fetch_depth" value="4"/>

                                  <property name="hibernate.default_batch_fetch_size" value="365"/>

                              </properties>

                          </persistence-unit>

                      </persistence>

                       

                      log4j.properties

                      log4j.rootCategory=TRACE, FILE

                       

                      log4j.logger.com.dappit.Dapper.parser=ERROR

                      log4j.logger.org.w3c.tidy=FATAL

                       

                      log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender

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

                      log4j.appender.CONSOLE.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c - %m%n

                       

                      log4j.appender.FILE=org.apache.log4j.DailyRollingFileAppender

                      log4j.appender.FILE.File=${jboss.server.log.dir}/myapp.log

                      log4j.appender.FILE.Append=true

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

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

                      log4j.appender.FILE.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %40.40C.%-20.20M(%3.3L) %-6.6p:%m%n

                       

                      log4j.logger.myapp=TRACE, FILE, CONSOLE

                      log4j.additivity.myapp=false

                       

                      log4j.logger.org.hibernate=WARN, FILE

                      log4j.additivity.org.hibernate=false

                       

                      # The PERF loggers logs to a separate performance log-file to avoid polluting and to ease future

                      # parsing and interpretation of performance.

                      log4j.appender.PERF=org.apache.log4j.DailyRollingFileAppender

                      log4j.appender.PERF.File=${jboss.server.log.dir}/myapp.perf.log

                      log4j.appender.PERF.Append=true

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

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

                      log4j.appender.PERF.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %m%n

                      log4j.logger.performance=TRACE, PERF

                       

                      console output

                      08:11:16,406 INFO  [stdout] (http--127.0.0.1-8080-1) Hibernate:

                      08:11:16,407 INFO  [stdout] (http--127.0.0.1-8080-1)     SELECT

                      08:11:16,407 INFO  [stdout] (http--127.0.0.1-8080-1)         gp.*

                      08:11:16,408 INFO  [stdout] (http--127.0.0.1-8080-1)     FROM

                      ...

                      ...

                       

                      server.log

                      08:11:16,013 INFO  [stdout] (http--127.0.0.1-8080-1) Hibernate:

                      08:11:16,014 INFO  [stdout] (http--127.0.0.1-8080-1)     SELECT

                      08:11:16,014 INFO  [stdout] (http--127.0.0.1-8080-1)         gp.*

                      08:11:16,015 INFO  [stdout] (http--127.0.0.1-8080-1)     FROM

                      ...

                      ...

                      • 9. Re: Hibernate' query logging doesn't work any more
                        Juergen Zimmermann Master

                        The only significant difference I see is that you're having a log4j.properties file. In which directory do you have log4j.properties?

                        • 10. Re: Hibernate' query logging doesn't work any more
                          Are Tysnes Newbie

                          /src/main/resources in the webapp project

                           

                          and it's located in WEB-INF\classes in the war file

                           

                          I doubt the log4j file has impact on the server.log .. the sql is not logged in my application log declared in log4j.properties.

                          • 11. Re: Hibernate' query logging doesn't work any more
                            Juergen Zimmermann Master

                            org.hibernate.engine.jdbc.spi.SqlStatementLogger is the replacment for org.hibernate.SQL. See  https://issues.jboss.org/browse/AS7-1522

                            • 12. Re: Hibernate' query logging doesn't work any more
                              Scott Marlow Master

                              As per the below linked code change, "org.hibernate.SQL" will soon work again for logging SQL statements.  When that happens, "org.hibernate.engine.jdbc.spi.SqlStatementLogger" will no longer work.

                               

                              https://github.com/hibernate/hibernate-core/commit/75e0ba4ce353629beee937a447d8252069fddcb0