How to log all generated SQL by Liquibase?

General Discussion
1

Hi everyone,

I’m using liquibase-core 4.25.1, Spring Boot in some outdated version 4 and Log4j2 included by Spring Boot. Some of my Liquibase migrations fail with possibly SQL syntax errors, but I don’t see the actual generated SQL in the exception message at all. It only mentions some syntax error and possible root causes to check, but without the actual SQL it’s not of much help. I didn’t generate that SQL on my own, but was just using indexExists from Liquibase.

<changeSet author="dbr" id="0.9.7-HRP-143-aaaaj" dbms="db2i">
    <preConditions onFail="MARK_RAN">
        <not>
            <indexExists tableName="AC_COSTCENTER" indexName="AC_COSTCENTER_UX"/>
        </not>
    </preConditions>
    <createIndex indexName="AC_COSTCENTER_UX" tableName="AC_COSTCENTER" unique="true">
        <column name="COMPANY_ID"/>
        <column name="KEY"/>
    </createIndex>
</changeSet>

From my understanding Liquibase should be able to log the SQL at some log level below INFO. Though, whatever I try I don’t get ANY log messages from Liquibase below that level. I’m able to switch between ERROR and INFO, so my configs are appliedat leats partly, but I don’t get anything below INFO and therefore most likely no SQL.

The following is my property for Spring Boot and according to different sources this should even work with my older Spring Boot. As I’m able to switch between ERROR and INFO, I guess it works in general.

logging.level.liquibase=TRACE

The following is Log4j2, but not sure about if the logger name is correct etc. Switching between ERROR and INFO seems to work here as well, e.g. with INFO in Spring Boot and ERROR in Log4j2, I only get the error messages etc. But again, nothing below INFO.

<Loggers>
	<Root level="WARN">
		<AppenderRef ref="console" />
		<AppenderRef ref="file"    />
	</Root>
	<Logger name="liquibase"            level="TRACE" />
	<Logger name="net.veda.appmediator" level="WARN"  />
</Loggers>

So how do I get the SQL logged or anything below INFO to check my settings?

Thanks!

2

For some reason, that line doesn’t work at all. When I switch TRACE to ERROR I still get INFO logged. OTOH, the following with explicit logger names does have an effect:

<Logger name="liquibase.changelog"   level="ALL" />
<Logger name="liquibase.command"     level="ALL" />
<Logger name="liquibase.executor"    level="ALL" />
<Logger name="liquibase.lockservice" level="ALL" />
<Logger name="liquibase.ui"          level="ALL" />
<Logger name="liquibase.util"        level="ALL" />

For whichever line I switch ALL to ERROR, the corresponding INFO logs disappear. Though, the line containing executor doesn’t seem to have any effect, nothing is logged with that logger name.

3

You need to set sql-log-level. Details can be found here:

4

I’ve tried that already and it doesn’t work, there’s no additional logging output, regardless of the configured log level. Though, what I needed to do to get additional output below INFO is setting the following property:

-Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager

Now I get more output from more loggers with e.g. DEBUG, but still no SQL at all. Though, I’m able to disable individual loggers until I get no output at all anymore, so the SQL is simply not there. When looking at the code, there’s already a default log level for SQL, so with a proper log manager in place the system property to override that shuldn’t be necessary anway.

SHOW_AT_LOG_LEVEL = builder.define("logLevel", Level.class)
                .setDescription("Level to log SQL statements to")
                .setValueHandler(ConfigurationValueConverter.LOG_LEVEL)
                .setDefaultValue(Level.FINE)
                .build();

<Logger name="liquibase.changelog"      level="ERROR" />
<Logger name="liquibase.command"        level="ERROR" />
<Logger name="liquibase.configuration"  level="ERROR" />
<Logger name="liquibase.executor"       level="ERROR" />
<Logger name="liquibase.ext"            level="ERROR" />
<Logger name="liquibase.lockservice"    level="ERROR" />
<Logger name="liquibase.parser"         level="ERROR" />
<Logger name="liquibase.servicelocator" level="ERROR" />
<Logger name="liquibase.snapshot"       level="ERROR" />
<Logger name="liquibase.ui"             level="ERROR" />
<Logger name="liquibase.util"           level="ERROR" />

ERROR means no logs anymore, ALL logs with level DEBUG, but no SQL. And even witht he log manager, the parent-child relationship of logger names known for log4j still don’t work for some reason:

<Logger name="liquibase" level="ERROR" />

That line on its own has no effect at all. The following line in my Spring Boot application does have an effect as well:

logging.level.liquibase=TRACE

So the problem really seems to be that SQL logs aren’t generated at all. There isn’t anything more log related I could set up and enable.

5

The following is the code in Liquibase:

Level sqlLogLevel = SqlConfiguration.SHOW_AT_LOG_LEVEL.getCurrentValue();
log.log(sqlLogLevel, statement, null);

So the system property really only influences the log level used, but if anything is actually logged at all depends on the logging backend and its configuration and stuff. And the “liquibase.executor” for some reasons doesn’t provide anything of use in my case.

2024-01-19 18:29:09.347 DEBUG LAP3738 --- [           main] l.executor                               : Changelog query completed.
2024-01-19 18:29:09.954 DEBUG LAP3738 --- [           main] l.executor                               : Changelog query completed.
2024-01-19 18:29:10.633 DEBUG LAP3738 --- [           main] l.executor                               : Changelog query completed.
2024-01-19 18:29:12.083 DEBUG LAP3738 --- [           main] l.executor                               : Changelog query completed.
2024-01-19 18:29:12.779 DEBUG LAP3738 --- [           main] l.executor                               : Changelog query completed.
2024-01-19 18:29:12.779 DEBUG LAP3738 --- [           main] l.executor                               : Lock Database
2024-01-19 18:29:13.710 DEBUG LAP3738 --- [           main] l.executor                               : Changelog query completed.
2024-01-19 18:29:14.617 DEBUG LAP3738 --- [           main] l.executor                               : Changelog query completed.
2024-01-19 18:29:14.742 DEBUG LAP3738 --- [           main] l.executor                               : Changeset db/migration/0.9.7/db2i-01-init.xml::0.9.7-HRP-143-aaaaj::dbr
2024-01-19 18:29:18.774 ERROR LAP3738 --- [           main] l.changelog                              : ChangeSet db/migration/0.9.7/db2i-01-init.xml::0.9.7-HRP-143-aaaaj::dbr encountered an exception.
2024-01-19 18:29:18.871 DEBUG LAP3738 --- [           main] l.executor                               : Release Database Lock
2024-01-19 18:29:19.560 DEBUG LAP3738 --- [           main] l.executor                               : Changelog query completed.
2024-01-19 18:29:20.182 ERROR LAP3738 --- [           main] o.s.b.SpringApplication                  : Application run failed
6

Looks like SQL logging simply doesn’t work currently, I’m not the only one seeing this:

7

Very strange, We’re using 4.25.0 and are seeing the sql that executed using sql-log-level=INFO:

Starting Liquibase at 13:38:39 (version 4.25.0 #3966 built at 2023-11-10 23:07:29 UTC)

[2024-01-22 13:40:22] INFO [liquibase.ui] Running Changeset: com/X/commercial/scoring/filed/oracle/3.x/db.changelog-3.0.0-cleanup.xml::cleanup-app-log-180days::X
[2024-01-22 13:40:22] INFO [liquibase.executor] DELETE FROM APP_LOG WHERE MESSAGE_DATETIME < (SYSDATE - 180)
[2024-01-22 13:40:22] INFO [liquibase.executor] 0 row(s) affected
[2024-01-22 13:40:22] INFO [liquibase.changelog] Custom SQL executed
[2024-01-22 13:40:22] INFO [liquibase.changelog] ChangeSet com/X/commercial/scoring/filed/oracle/3.x/db.changelog-3.0.0-cleanup.xml::cleanup-app-log-180days::X ran successfully in 19ms
[2024-01-22 13:40:22] INFO [liquibase.executor] UPDATE CLSCF.DATABASECHANGELOG SET COMMENTS = 'delete records from app_log which are over 180 days old', CONTEXTS = NULL, DATEEXECUTED = SYSTIMESTAMP, DEPLOYMENT_ID = '5930818037', EXECTYPE = 'RERAN', LABELS = NULL, MD5SUM = '9:ffbd0180947edaaff1c0920125d8a049', ORDEREXECUTED = 7674 WHERE ID = 'cleanup-app-log-180days' AND AUTHOR = 'X' AND FILENAME = 'com/X/commercial/scoring/filed/oracle/3.x/db.changelog-3.0.0-cleanup.xml'
[2024-01-22 13:40:22] INFO [liquibase.executor] 1 row(s) affected
8

So whats your logging framework and stuff? I’m using log4j2 as the backend and it’s jul-bridge, especially for Liquibase. But SLF4J is available as well, forwarded to log4j2 again from my understanding.

Additionally, do you have log output like the following? I don’t see it in your excerpt, but if you don’t have it, that might be another hint for something broken for me.

l.executor : Changelog query completed.

9

I’m finally able to see the SQL! :slight_smile: I needed to set the following system properties, the log setting in Spring Boot and create individual loggers.

-Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager
-Dlog4j2.disable.jmx=true
-Dliquibase.sql.logLevel=DEBUG

logging.level.liquibase=TRACE

Setting the LogManager is necessary because otherwise not all log messages are forwarded at all, the executor for example was missing. With a set LogManager I got some warning about JMX and therefore simply disabled it.

The log level for SQL needs to be set explicitly because the default of FINE doesn’t seem to be properly mapped into the JUL world. When I configure TRACE, liquibase.ui was partly logging warnings about TRACE not being supported and INFO will be used. But that’s the only warning I got within a lot of other log statements, while I assume TRACE not being supported at all for all other log statements as well. Not sure why liquibase.ui logged that instead of e.g. the executor…

WARNING: Unknown log level TRACE. Defaulting to ‘INFO’

Last but not least, all the loggers need to be defined explicitly in my case to individuall configure log levels. Having e.g. only the first line and the others commented, I still get all other log messages because of level TRACE in the Spring Boot config. That shouldn’t be the case in a proper parent-client naming relationship.

<Logger name="liquibase"                level="ERROR" />
<Logger name="liquibase.changelog"      level="INFO"  />
<Logger name="liquibase.command"        level="ERROR" />
<Logger name="liquibase.configuration"  level="ERROR" />
<Logger name="liquibase.database"       level="ERROR" />
<Logger name="liquibase.executor"       level="ERROR" />
<Logger name="liquibase.ext"            level="ERROR" />
<Logger name="liquibase.integration"    level="ERROR" />
<Logger name="liquibase.lockservice"    level="ERROR" />
<Logger name="liquibase.parser"         level="ERROR" />
<Logger name="liquibase.servicelocator" level="ERROR" />
<Logger name="liquibase.snapshot"       level="ERROR" />
<Logger name="liquibase.ui"             level="ERROR" />
<Logger name="liquibase.util"           level="ERROR" />

2024-01-22 DEBUG l.executor  : Changeset db/migration/[...].xml::[...]
2024-01-22 DEBUG l.executor  : CREATE TABLE "[...]".[...]
2024-01-22 DEBUG l.executor  : 0 row(s) affected
2024-01-22  INFO l.changelog : Table BRANCH created
2024-01-22  INFO l.changelog : ChangeSet db/migration/[...].xml::[...] ran successfully in 7029ms
2024-01-22 DEBUG l.executor  : INSERT INTO "[...]".DATABASECHANGELOG ("ID", AUTHOR, FILENAME, DATEEXECUTED, ORDEREXECUTED, MD5SUM, DESCRIPTION, COMMENTS, EXECTYPE, CONTEXTS, LABELS, LIQUIBASE, DEPLOYMENT_ID) VALUES ('[...]', '[...]', 'db/migration/[...].xml', CURRENT TIMESTAMP, 2, '9:513f549e75cd3aacb010696f1ae9cd38', 'createTable tableName=BRANCH', '', 'EXECUTED', NULL, NULL, '4.25.1', '5946791675')
2024-01-22 DEBUG l.executor  : 1 row(s) affected
2024-01-22 DEBUG l.executor  : Changelog query completed.
10

I’m running the Liquibase CLI via Linux.

11

If using Logback, adding <logger name="liquibase.executor" level="DEBUG" /> worked for me.