Logging issues with 3.0.5

General Discussion
1

Hi Developers,

In 3.0.5 release, I found some strange behaviour with logging. First of all, your 2 new methods in liquibase.logging.Logger interface breaked all known Logger implementations, causing exceptions like this:

java.lang.AbstractMethodError: liquibase.ext.logging.slf4j.Slf4jLogger.setChangeLog(Lliquibase/changelog/DatabaseChangeLog;)V
    at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:44)
    at liquibase.changelog.DatabaseChangeLog.validate(DatabaseChangeLog.java:144)
    at liquibase.Liquibase.update(Liquibase.java:133)
    at com.jpatry.schemautils.LiquibaseHibernateDiffTool.applyFullChangelog(LiquibaseHibernateDiffTool.java:118)
    at com.jpatry.schemautils.LiquibaseHibernateDiffTool.main(LiquibaseHibernateDiffTool.java:78)
  
Second: when I removed all third-party logger packages, some strange null-s appeard in the log:

INFO 2013.09.28. 10:35:liquibase: null: null: Successfully acquired change log lock
INFO 2013.09.28. 10:35:liquibase: null: null: Creating database history table with name: PUBLIC.DATABASECHANGELOG
INFO 2013.09.28. 10:35:liquibase: null: null: Reading from PUBLIC.DATABASECHANGELOG
INFO 2013.09.28. 10:35:liquibase: null: null: Reading from PUBLIC.DATABASECHANGELOG
INFO 2013.09.28. 10:35:liquibase: C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml: C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml::1376422807437-1::Erdei Zoltan (generated): Table EMPLOYEE created
INFO 2013.09.28. 10:35:liquibase: C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml: C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml::1376422807437-1::Erdei Zoltan (generated): ChangeSet C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml::1376422807437-1::Erdei Zoltan (generated) ran successfully in 16ms

Third: when another changelog file (changelog2.xml) starts, the default logger remembers, and writes the first changelog file:

INFO 2013.09.28. 10:35:liquibase: C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml: null: Successfully acquired change log lock
INFO 2013.09.28. 10:35:liquibase: C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml: null: Creating database history table with name: PUBLIC.DATABASECHANGELOG
INFO 2013.09.28. 10:35:liquibase: C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml: null: Reading from PUBLIC.DATABASECHANGELOG
INFO 2013.09.28. 10:35:liquibase: C:/Development/JpaLiquibase3Try/src/main/resources/database/changelog.xml: null: Reading from PUBLIC.DATABASECHANGELOG
INFO 2013.09.28. 10:35:liquibase: C:/Development/JpaLiquibase3Try/changelog2.xml: C:/Development/JpaLiquibase3Try/changelog2.xml::1376422807437-1-22::Erdei Zoltan (generated): Table EMPLOYEE created
INFO 2013.09.28. 10:35:liquibase: C:/Development/JpaLiquibase3Try/changelog2.xml: C:/Development/JpaLiquibase3Try/changelog2.xml::1376422807437-1-22::Erdei Zoltan (generated): ChangeSet C:/Development/JpaLiquibase3Try/changelog2.xml::1376422807437-1-22::Erdei Zoltan (generated) ran successfully in 0ms

(I think all of these could be fixed by finding another way to write the actual changeLog/changeSet information, not involving the Logger to store it - just my opinion)

Thanks,
Zoltán

2

FYI, the liquibase-slf4j logging implementation has been updated to support the new methods in 3.0.5.

http://search.maven.org/#artifactdetails|com.mattbertolini|liquibase-slf4j|1.2.0|jar

As for why those methods were implemented and why they are prone to null, I have no idea. It does seem a bit odd to me to have null capable data being printed in a logger like this. I would have made this data available to the logger via something like a MDC parameter but since this is an internal logger, it can’t rely on that kind of support.

3

Thanks, I improved the default logger output when there are null values and added code to make sure the changelog file is cleared out of the logger when it is done.


The methods were added so that we can better output the more of the context around a particular log message and be able to tie it back to a changeSet or changeLogFile. It probably should have been added as a sub-interface to avoid breaking existing integrations like the slf4j one, sorry about that.


I had originally implemented it as more of a generic MDC like in slf4j, but decided instead to go for a more descriptive implementation since we have a more constrained scenario than the more generic scenarios that slj4f needs to handle.


Nathan