Call getNextException to see the cause : How to make Hibernate / JPA show the DB server message for an exception

Question

I am using Postgresql, Hibernate and JPA. Whenever there is an exception in the database, I get something like this which is not very helpful as it does not show what really went wrong on the DB server.

Caused by: java.sql.BatchUpdateException: Batch entry 0 update foo set ALERT_FLAG='3' was aborted.  Call getNextException to see the cause.
    at org.postgresql.jdbc2.AbstractJdbc2Statement$BatchResultHandler.handleError(AbstractJdbc2Statement.java:2621)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1837)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:407)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2754)
    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)
    at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
    at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
    ... 82 more

I want the exception message from the database to appear in the application's log.

I came across this article which uses an Aspect to populate the exception chain which is otherwise not populated properly in case of SQLExceptions.

Is there a way to fix this without using Aspects or any custom code. Ideal solution would involve only config file changes.

Solution 1

There is no need to write any custom code to achieve this - Hibernate will log the exception cause by default. If you can't see this, Hibernate logging must not be set up correctly. Here's an example with slf4j+log4j, and using Maven for dependency management.

src/main/java/pgextest/PGExceptionTest.java

public class PGExceptionTest {

    public static void main(String[] args) throws Exception {

        EntityManagerFactory entityManagerFactory = Persistence.createEntityManagerFactory(
                "pgextest");
        EntityManager entityManager = entityManagerFactory.createEntityManager();
        entityManager.getTransaction().begin();
        // here I attempt to persist an object with an ID that is already in use
        entityManager.persist(new PGExceptionTestBean(1));
        entityManager.getTransaction().commit();
        entityManager.close();
    }
}

src/main/resources/log4j.properties

log4j.rootLogger=ERROR, stdout

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%5p [%t] - %m%n

src/main/resources/META-INF/persistence.xml

<persistence 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_2_0.xsd"
        version="2.0">
    <persistence-unit name="pgextest">
        <properties>
            <property name="javax.persistence.jdbc.driver" value="org.postgresql.Driver"/>
            <property name="javax.persistence.jdbc.url" value="jdbc:postgresql://localhost/pgextest"/>
            <property name="javax.persistence.jdbc.user" value="postgres"/>
            <property name="javax.persistence.jdbc.password" value="postgres"/>
            <property name="hibernate.dialect" value="org.hibernate.dialect.PostgreSQLDialect"/>
            <property name="hibernate.jdbc.batch_size" value="5"/>
        </properties>
    </persistence-unit>
</persistence>

pom.xml

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">

    <modelVersion>4.0.0</modelVersion>

    <groupId>pgextest</groupId>
    <artifactId>pgextest</artifactId>
    <version>0.0.1-SNAPSHOT</version>

    <build>
        <plugins>
            <plugin>
                <artifactId>maven-compiler-plugin</artifactId>
                <configuration>
                    <source>1.6</source>
                    <target>1.6</target>
                </configuration>
            </plugin>
        </plugins>
    </build>

    <dependencies>
        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-entitymanager</artifactId>
            <version>3.6.9.Final</version>
        </dependency>   

        <dependency>
            <groupId>postgresql</groupId>
            <artifactId>postgresql</artifactId>
            <version>9.1-901.jdbc4</version>
            <scope>runtime</scope>
        </dependency>

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-log4j12</artifactId>
            <version>1.6.1</version>
            <scope>runtime</scope>
        </dependency>

        <dependency>
            <groupId>log4j</groupId>
            <artifactId>log4j</artifactId>
            <version>1.2.15</version>
            <scope>runtime</scope>
        </dependency>
    </dependencies>
</project>

Executing the main method will then log the following:

ERROR [main] - Batch entry 0 insert into PGExceptionTestBean (label, id) values (NULL, '1') was aborted.  Call getNextException to see the cause.
ERROR [main] - ERROR: duplicate key value violates unique constraint "pgexceptiontestbean_pkey"

It's probably worth mentioning that you can disable the JDBC batching that wraps the original exception by setting the property hibernate.jdbc.batch_size to 0 (needless to say you probably don't want to do this in production.)

Solution 2

This worked for me to get the exception message which caused the problem (Hibernate 3.2.5.ga):

catch (JDBCException jdbce) {
    jdbce.getSQLException().getNextException().printStackTrace();
}

Solution 3

I think Aspect Programming is a better solution to solve this kind of problem.

But, if you want to write a custom code to do that, you can catch SqlException and loop through it and log each exception. Something like this should work.

try {
 // whatever your code is
} catch (SQLException e) {
    while(e!= null) {
      logger.log(e);
      e = e.getNextException();
    }
}

Solution 4

For me the exception was a PersistenceException, so I had to do this:

try {
//...
} catch (javax.persistence.PersistenceException e) {
    log.error(((java.sql.BatchUpdateException) e.getCause().getCause()).getNextException());
}

Solution 5

try {
 // code
} catch (SQLException e) {      
  for (Throwable throwable : e) {
        log.error("{}", throwable);
  }
}

View more solutions

Comments

[Dojo]

Yes! I knew what the exception message was to be expected so searched that in the console log and I found one tiny line with the message. So, it does show up but without the bells and whistles of a complete stack trace. That's good enough for me.

[Yar]

Is it possible to do something like this in Play 2.2.x? It uses logback for logging

[Tom Saleeba]

Love the idea. The placeholders don't get replaced for me on log4j 1.2.15 so I'll write my own message to go with the traces.

[Picrochole]

In my case "java.sql.BatchUpdateException: Batch entry 0 delete from account where id=32 was aborted. Call getNextException to see the cause..." org.slf4j+log4j was the solution. Log level has to be set to DEBUG to see the root cause.

[Victor Grazi]

This does not look right at all. You are calling getNextException three times for every exception!!

[Ankit Bansal]

You can optimize it to one by taking variable out... but technically there is nothing wrong in it.. it will give you same exception since it's a get...

[Hardik Thaker]

you can directly go with, catch (SQLException e) { e.getNextException().printStackTrace(); }

[Noumenon]

@Victor Grazi was correct the first time. getNextException() gets a different exception every time it is called until it finally returns null.