Precondition onFailMessage not logged when onFail="HALT"

On RC7 when I use a that has onFail=“HALT” and an onFailMessage, if the precondition fails, the log output doesn’t contain my onFailMessage.

This is awkward because my build team doesn’t understand why LB failed. In fact, the only way the log will give me any indication of which changeset it was on is if I enable debug-level logging.

Request:  A precondition failure should always output the onFailMessage regardless of what onFail is set to. I should be able to see the onFailMessage without changing the logLevel from the default.

Could this be fixed?

Suggestion:  Looks like a simple change in PreconditionContainer.java check(…) – would a LogFactory.getLogger().warning/info call for the HALT condition make sense? Or perhaps in ChangeSet.java execute(…)?

Example:

Precondition looks like:

<preConditions onFail="HALT" onFailMessage="Friendly Fail Message">
	<sqlCheck expectedResult="purposely fail this">select 'abc'</sqlCheck>
</preConditions>

Command-line output is:

Liquibase Update Failed: Preconditions Failed.&nbsp; For more information, use the --logLevel flag)

Debug-level log output is:

...
liquibase:FINEST: Changeset <filename>.xml::1::<author>::(Checksum: 3:<checksum>)
liquibase:FINEST: Executing QUERY database command: select 'abc'
liquibase:FINEST: Release Database Lock
liquibase:FINEST: Executing UPDATE database command: UPDATE [dbo].[DATABASECHANGELOGLOCK] SET [LOCKED] = 0, [LOCKEDBY] = NULL, [LOCKGRANTED] = NULL WHERE [ID] = 1
liquibase:INFO: Successfully released change log lock
liquibase:INFO: Preconditions Failed

And that needs some training & time to understand that “the last change set mentioned in this very verbose log was x::y::z, and it turned out to be a precondition failure, therefore I have to look in the source to understand what a failure on precondition x::y::z means”, instead of “oh, the problem is due to !”

In constrast, if I use onFail=“CONTINUE”, the output is beautiful. Here is a sample, with the default logging level:

...
liquibase:INFO: Continuing past: <filename>.xml::1::<author>::(Checksum: 3:<checksum>) despite precondition failure:
 Friendly Fail Message
liquibase:INFO: ChangeSet parameter_verification.xml::1::clean ran successfully in 6ms
...

The onFailMessage is also listed when onFAIL=“MARK_RAN” or onFAIL=“WARN”

But I prefer halting in our environment.

A big thanks for all your work! I’m willing to test any fix :slight_smile:

What are you using to run liquibase?

When I add a halt precondition, I get output like this:

INFO 11/23/10 11:58 PM:liquibase: Preconditions Failed
liquibase.exception.MigrationFailedException: Migration failed for change set changelogs/common/common.tests.changelog.xml::defaultValueTest-2::nvoxland:
    Reason:
          changelogs/mysql/complete/root.changelog.xml : Table saghaskdgas does not exist
:
          Caused By: Preconditions Failed

from the command line.

I did increase the logging level to severe so it is always logged.  Are you redirecting output?  The message may be going to stderr.

Nathan

Can you post the XML and command line you used?  I’ll test it against SQL Server.

Driver in use is type 4 Microsoft SQL Server JDBC Driver 2.0 (from http://www.microsoft.com/downloads/en/details.aspx?FamilyID=99b21b65-e98f-4a61-b811-19912601fdc9&displaylang=en). Now that I think about it, I haven’t tried their 3.0 driver… will test.

I’m using command line similar to this - no redirection:

call “…\2.0RC7\liquibase.bat” --driver=com.microsoft.sqlserver.jdbc.SQLServerDriver --classpath="…\2.0RC7\liquibase.jar;…\extension\classes" --changeLogFile=“change.xml” --url=“jdbc:sqlserver://…;instanceName=…;DatabaseName=…”  --username="…" --password="…" --logLevel=debug --logFile="…\Log\liquibase.log" update

(Also tried redirecting to stderr but the file is empty)

The failing precondition for this test is:

Getting output similar to previous post.

I am testing it with your sample XML, both in a changeSet and a changelog wide preconditions block inside a larger sample XML file I have.  I ran it as “…\liquibase-2.0-rc7-bin\liquibase.bat --defaultsFile=liquibase.mysql.properties update” with a defaultsFile like:

    classpath: ..;../jdbc-drivers/all/mysql-5.0.4/mysql-connector-java-5.0.4-bin.jar;../../../../../liquibase-core/target/test-classes;../../../../../samples/liquibase-ext-change/target/classes;../../../../../liquibase-integration-tests/target/test-classes/packaged-changelog.jar changeLogFile=changelogs/mysql/complete/root.changelog.xml username=liquibase password=liquibase url=jdbc:mysql://localhost/liquibase driver=com.mysql.jdbc.Driver logLevel=DEBUG contexts=test

I hadn’t been using the logFile attribute, when I added that I stillg got the “… table does not exist” message in the log file, and on stdout.

Nathan

The driver should not matter

Nathan