Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.0.0
    • Component/s: None

      Description

      From http://liquibase.org/forum/index.php?topic=221.0

      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">
      <changeSet author="jsmith" id="1" runOnChange="true">
      <preConditions onFail="MARK_RAN">
      <viewExists viewName="departments_vw"/>
      </preConditions>
      <dropView viewName="departments_vw"/>
      </changeSet>
      <changeSet author="jsmith" id="2" runOnChange="true">
      <createView viewName="departments_vw">
      select id, dname from departments
      </createView>
      </changeSet>
      </databaseChangeLog>

      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<SqlVisitor>) line: 58)

      public Object execute(StatementCallback action, List<SqlVisitor> 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<SqlVisitor>) line: 58
      JdbcExecutor.query(SqlStatement, ResultSetExtractor, List<SqlVisitor>) line: 124
      JdbcExecutor.query(SqlStatement, RowMapper, List<SqlVisitor>) line: 132
      JdbcExecutor.queryForObject(SqlStatement, RowMapper, List<SqlVisitor>) line: 140
      JdbcExecutor.queryForObject(SqlStatement, Class, List<SqlVisitor>) 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<DiffStatusListener>) line: 203
      DatabaseSnapshotGeneratorFactory.createSnapshot(Database, String, Set<DiffStatusListener>) 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

        Attachments

          Activity

            People

            • Reporter:
              nvoxland Nathan Voxland
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: