kind of "exception swallowing"

Hello, I would like to signal a kind of “exception swallowing”.

I was testing LiquiBase Version: 2.0-rc2-SNAPSHOT against a test HSQL database whith the last snaphot jar of HSQLDB 1.9 released on 1 Nov (after RC6).

I was running the command
“liquibase --logLevel=debug --changeLogFile=update.xml update” whith my changelongs including this xml:

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

<databaseChangeLog xmlns=“http://www.liquibase.org/xml/ns/dbchangelog/1.9”
   xmlns:xsi=“http://www.w3.org/2001/XMLSchema-instance”
   xsi:schemaLocation=“http://www.liquibase.org/xml/ns/dbchangelog/1.9 http://www.liquibase.org/xml/ns/dbchangelog/dbchangelog-1.9.xsd”>
   
       
           
       
       
   
   
       
           select id, dname from departments
       
   

and I had this error:

INFO 12/11/09 22.55:liquibase: Reading from DATABASECHANGELOG
DEBUG 12/11/09 22.55:liquibase: Running Changeset:latest/vw/departments_vw.xml::1::jsmith::(Checksum: 2:d47fa6915fc3c813b6a0b666cdcb2601)
DEBUG 12/11/09 22.55:liquibase: Changeset latest/vw/departments_vw.xml::1::jsmith::(Checksum: 2:d47fa6915fc3c813b6a0b666cdcb2601)
DEBUG 12/11/09 22.55:liquibase: Release Database Lock
INFO 12/11/09 22.55:liquibase: Successfully released change log lock
LiquiBase Update Failed: Precondition Error
INFO 12/11/09 22.55:liquibase: Precondition Error
liquibase.exception.MigrationFailedException: Migration failed for change set latest/vw/departments_vw.xml::1::jsmith:
    Reason:

         update.xml : Error getting jdbc:hsqldb:hsql://localhost/testdb view with liquibase.statement.core.GetViewDefinitionStatement@a00185
:
         Caused By: Precondition Error
at liquibase.changelog.ChangeSet.execute(ChangeSet.java:197)
at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:26)
at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:39)
at liquibase.Liquibase.update(Liquibase.java:103)
at liquibase.integration.commandline.Main.doMigration(Main.java:664)
at liquibase.integration.commandline.Main.main(Main.java:105)
Caused by: liquibase.exception.PreconditionErrorException: Precondition Error
at liquibase.precondition.core.ViewExistsPrecondition.check(ViewExistsPrecondition.java:39)
at liquibase.precondition.core.AndPrecondition.check(AndPrecondition.java:24)
at liquibase.precondition.core.PreconditionContainer.check(PreconditionContainer.java:199)
at liquibase.changelog.ChangeSet.execute(ChangeSet.java:163)
… 5 more

Now, the problem it’s not the error by itself, but the fact that I had no way to understand the real cause of the error!

I debugged the application and here’s what I discovered:

the original DatabaseException is caught in class
HsqlDatabaseSnapshotGenerator(JdbcDatabaseSnapshotGenerator).readView(ResultSet, Database) line: 146:
in this fragment of code:
try {
           view.setDefinition(database.getViewDefinition(rs.getString(“TABLE_SCHEM”), name));
       } catch (DatabaseException e) {
           throw new DatabaseException("Error getting " + database.getConnection().getURL() + " view with " + new GetViewDefinitionStatement(view.getSchema(), name), e);
       }

and is generated in this fragment of code (in JdbcExecutor.execute(StatementCallback, List) line: 58)

public Object execute(StatementCallback action, List sqlVisitors) throws DatabaseException {
       DatabaseConnection con = database.getConnection();
       Statement stmt = null;
       try {
           stmt = ((JdbcConnection) con).getUnderlyingConnection().createStatement();
           Statement stmtToUse = stmt;

           return action.doInStatement(stmtToUse);
       }
       catch (SQLException ex) {
           // Release Connection early, to avoid potential connection pool deadlock
           // in the case when the exception translator hasn’t been initialized yet.
           JdbcUtils.closeStatement(stmt);
           stmt = null;
           throw new DatabaseException("Error executing SQL " + StringUtils.join(applyVisitors(action.getStatement(), sqlVisitors), ", "), ex);
       }
       finally {
           JdbcUtils.closeStatement(stmt);
       }
   }

reached with the following stack:
JdbcExecutor.execute(StatementCallback, List) line: 58
JdbcExecutor.query(SqlStatement, ResultSetExtractor, List) line: 124
JdbcExecutor.query(SqlStatement, RowMapper, List) line: 132
JdbcExecutor.queryForObject(SqlStatement, RowMapper, List) line: 140
JdbcExecutor.queryForObject(SqlStatement, Class, List) line: 149
JdbcExecutor.queryForObject(SqlStatement, Class) line: 145
HsqlDatabase(AbstractDatabase).getViewDefinition(String, String) line: 608
HsqlDatabaseSnapshotGenerator(JdbcDatabaseSnapshotGenerator).readView(ResultSet, Database) line: 146
HsqlDatabaseSnapshotGenerator(JdbcDatabaseSnapshotGenerator).readViews(DatabaseSnapshot, String, DatabaseMetaData) line: 263
HsqlDatabaseSnapshotGenerator(JdbcDatabaseSnapshotGenerator).createSnapshot(Database, String, Set) line: 203
DatabaseSnapshotGeneratorFactory.createSnapshot(Database, String, Set) line: 69
ViewExistsPrecondition.check(Database, DatabaseChangeLog, ChangeSet) line: 37
PreconditionContainer(AndPrecondition).check(Database, DatabaseChangeLog, ChangeSet) line: 24
PreconditionContainer.check(Database, DatabaseChangeLog, ChangeSet) line: 199
ChangeSet.execute(DatabaseChangeLog, Database) line: 163
UpdateVisitor.visit(ChangeSet, DatabaseChangeLog, Database) line: 26
ChangeLogIterator.run(ChangeSetVisitor, Database) line: 39
Liquibase.update(String) line: 103
Main.doMigration() line: 664
Main.main(String[]) line: 105

The variable ex in the code above contains the real problem:
java.sql.SQLException: user lacks privilege or object not found: SYSTEM_VIEWS
and the message of the DatabaseException being thrown further clarify the problem:
Error executing SQL SELECT VIEW_DEFINITION FROM INFORMATION_SCHEMA.SYSTEM_VIEWS WHERE TABLE_NAME = ‘DEPARTMENTS_VW’ AND TABLE_SCHEMA=‘PUBLIC’

What appens at the end, unfortunately, is that neither of the messages is reported in the output of the program: conversely, the message reported:
Error getting jdbc:hsqldb:hsql://localhost/testdb view with liquibase.statement.core.GetViewDefinitionStatement@a00185 is quite “enigmatic”.

I’ve see that the DatabaseException is wrapped by a ErrorPrecondition and futher by a PrecoditionErrorException (ViewExistsPrecondition.check(Database, DatabaseChangeLog, ChangeSet) line: 39): when the output message is built, the following fragment of code is executed (PreconditionContainer.check(Database, DatabaseChangeLog, ChangeSet) line: 227 ):
catch (PreconditionErrorException e) {
           StringBuffer message = new StringBuffer();
           message.append("     “).append(e.getErrorPreconditions().size()).append(” preconditions failed").append(StreamUtil.getLineSeparator());
           for (ErrorPrecondition invalid : e.getErrorPreconditions()) {
               message.append("     ").append(invalid.toString());
               message.append(StreamUtil.getLineSeparator());
           }
here is invoked the method toString on the istance of the class ErrorPrecondition: this method does not print the real cause.
Here is an extract of my debugging environment (eclipse) where you may find the variables and some of their internal values, in particular I’ve found here the real “cause”(s) of the problem that aren’t reported in the program output.

invalid ErrorPrecondition  (id=1756)
cause DatabaseException  (id=1764)
cause DatabaseException  (id=1744)
cause SQLException  (id=1725)
cause null
detailMessage “user lacks privilege or object not found: SYSTEM_VIEWS” (id=1729)
detailMessage “Error executing SQL SELECT VIEW_DEFINITION FROM INFORMATION_SCHEMA.SYSTEM_VIEWS WHERE TABLE_NAME = ‘DEPARTMENTS_VW’ AND TABLE_SCHEMA=‘PUBLIC’” (id=1745)
detailMessage “Error getting jdbc:hsqldb:hsql://localhost/testdb view with liquibase.statement.core.GetViewDefinitionStatement@593f5a2f” (id=1774)
stackTrace null
changeLog DatabaseChangeLog  (id=1752)
precondition ViewExistsPrecondition  (id=45)

by the way: I don’t know why in HSQL 1.9 (snapshot) the object INFORMATION_SCHEMA.SYSTEM_VIEWS does’nt exists anymore: instead exists the object INFORMATION_SCHEMA.VIEWS…

Regards,
Duccio

Thanks for all the troubleshooting.  We definitely need to get the real message through on the stacktrace.  I created an issue for it: http://liquibase.jira.com/browse/CORE-514

Nathan