Logging Changes

Liquibase Development
1

I did some trial work on changing how the logging works in this branch https://github.com/liquibase/liquibase/tree/slf4j_test

It uses slf4j by default and therefore drops the whole “look up logging via service factory” pattern since it can rely on SLF4j, but it still keeps the liquibase.logger.LogFactory wrapper around slf4j.

This gives us a couple things:

  1. We can still bypass slf4j if we need, like in Ant by manually setting the LogFactory implementation.
  2. The log messages have a LogTarget enum param that specifies the type of log message it would be: standard log message, user-facing message, or a pipe-output message. The standard log implementation just logs them all via slf4j so however Liquibase is embedded will see all the message, but there is also a CommandLineLoggerFactory which handles the targets differently
  3. The Logger interface supports nested contexts for any log implementations that support that. SLF4j does not and I have not implemented it yet, but it should be useful for the command line logging and we may emulate it in the slf4j logger
  4. The Logger interface allows logging of progress on a task. I didn't implement anything for it yet, but would be useful in the command line logger at least.

The command line implementation needs to use direct Logback access in order to control the log level, but that should be the only use of logback and logback should not be a required dependency.

Take a look at the code, and let me know what you think

Nathan

2

Last chance for feedback on the logging changes that have gone into the dbmanul-merge branch before they head to master for the 3.6 release.

Nathan

3

Thanks for the reply, always great to get feedback.


Renaming LogFactory

The change is, unfortunately, definitely a major change. I had been planning on making it with liquibase 4 since I really don’t like making API-breaking changes, but it’s been a problem for far too long, and liquibase 4 is not moving as well as I would have liked. The logging cleanup dbmanul did also forced the issue as well.

Because it’s such an inherently breaking change, and is going to cause some redo of extensions regardless so I figured it would be best to focus on a good API going forward rather than keeping old names that may not work as well now. 

However, your point about non-logger extensions breaking because they are using the existing liquibase logging system is a very good point. There will be some changes they will need to make, but if we can avoid some of the code changes that is always best. 

So, I added back a liquibase.logger.LogFactory class with the same method signatures as before. 

Because I changed to a forced classname based logging the LogFactory version that takes a string guesses it is a classname or otherwise has to use Liquibase.class. It’s not ideal, but I had purposely not included the string-named loggers to provide more consistency in how logs are named across plugins. My guess is most people used class names or the empty getLog() method anyway, but does anyone feel very strongly that non-class-name log names should be supported?

For source-level compatibility, I also added back the non-LogTarget versions of the methods in Logger and renamed “error” back to “severe” and “warn” back to “warning”.

LoggerContext

The auto-closeable side of LoggerContext is nice because it lets you do:

}

and you don’t have to worry about not cleaning up the MDC at all.

However, the biggest reason for the LoggerContext was to provide hooks beyond to make the logging system useful for more than just writting strings to a text file. My idea is that LoggerContexts are a more complex object that allow parts of the program to more intelligently let the user know what is going on. Compared to standard MDC, the value can be an object rather than a string, and there are methods for showing progress on the current state. 

Liquibase has a lot of ways that it can be ran, from a standard command line app, to a command line app that pipes to others, to embedded in a server to integrated into GUIs. I’m trying to find a good way to have the liquibase code (and extensions) be able to have simple log.info() style calls and the way those messages are returned can be handled flexibly. 

In an server, the messages will just go to the log, but in a command line app you may want a more complex nested output like dbmanul’s TreeStyleLogger (which i took out for now) as an option, and in a GUI you may want to show progress dialogs for long-running operations. 

LoggerContext is trying to be a generic MDC yet add a few more features to allow better user interaction within each context.

LogTarget

LogTarget is another feature in my attempt to have a better unified way to have code simply log what it’s doing and have different Liquibase interfaces handle those messages in the best ways for them. 

SQL logging vs. regular logging is a good example of where we’ve seen the problem. There have been several attempts (including dbmanul) to introduce a SQL log level so that people can see what SQL has been ran (sometimes DML, sometimes queries, sometimes both), but a SQL log level doesn’t work well because where does it fit into the level hierarchy? It’s not really more severe than “severe”, but that is what you need to do to get only SQL. And if you do that, you always get SQL if you just want error messages.

LogTarget is basically the same as Markers, just a bit more constrained in what the available options are. It lets the code making a log message at any level be able to say what kind of message it is and leave it up to the logger as configured by the integration to handle it as it sees fit. 

One big help for the LogTarget is in the Liquibase 4 code: I simplified the database interaction so there is no longer the separate code paths for updateSql vs update mode and have a new “update and also output the SQL” mode. There is a common location that ALL sql calls to the database now go through that can simply log.info(LogTarget.SQL, sqlStatement) the statement as it goes to the database and the CLI can send the sql to the correct location independently from any logging it does.

Nathan


4

Hi Nathan,


sorry for the long delay, I finally took some time to look at the recent logging changes. Here are some things that came to my mind:
    why rename the LogFactory?
that will be a problem for custom plugins that don’t mess to much with logging but simply provide additional dsl elements or features for other databases. I’d suggest to at least keep a compatibility layer until Liquibase 4.
    I m not sure why you introduced the LoggerContext
MDC/NDC are a well known concepts and the only benefit seems to be the AutoCloseable implementation. Is this because Liquibase is a single threaded use case and we have no ThreadLocal cleanup, that is usually used with MDCs?
Creating something with a “push” method and freeing it up with a “close” feels awkward, too.
If you like that abstraction of a MDC, why not do something like this:
}
and this would not need the creation of another object.

What do you think?

    I am very skeptical about the LogTarget
Liquibase has a good separation of concerns. Usually no Change ever outputs any Sql directly but let some factory create it and Executor run it. The LogTarget seems to imply that one class/logger will be used to output user information, debug info, read sql and write sql. Actually I don’t think this is a common use case.

Just a guess: some user wants to suppress some of the logging caused by a verbose third party extension. But by lowering the LogLevel he also mutes the output of generated SQL and the CLI output and not just the stuff written to the log file. Most messages in liquibase are on a info level, but many production environments encourage warn level.
I havent used Log-Markers (even log4j2 seems to have them) so this may be only a concern cause I am only used to LogLevels for filtering messages.


Hope my remarks help and are not too critical, I really appreciate your work and the fresh breeze from dbmanul.

kind regards
Daniel

5

Hi Sorry for corrupting logging thread but I think It has something to do with this change.

As with 3.6.0-SNAPSHOT I’m trying to run migration pulling changelogs from war file… something like this:

http://www.liquibase.org/documentation/command_line.html should be changed with 3.6.0