How to log all generated SQL by Liquibase?

veda-tschoening · January 19, 2024, 11:16am

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!

veda-tschoening · January 19, 2024, 4:16pm

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.

daryldoak · January 19, 2024, 4:43pm

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

veda-tschoening · January 19, 2024, 5:06pm

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

github.com/liquibase/liquibase

Disable console logs for every changeset

opened 12:44PM - 24 Jan 22 UTC

closed 06:06PM - 01 Nov 23 UTC

baev

TypeEnhancement Logging ver4.7.1 needs_review needs_guidance

## Environment **Liquibase Version**: 4.7.1 **Liquibase Integration & Version**: <Pick one: CLI, maven, gradle, spring boot, servlet, etc.> **Liquibase Extension(s) & Version**: **Database Vendor & Version**: **Operating System Type & Version**: ## Description Since 4.7.1 every changeset is logged to SOUT, and it seems like there is no way to turn it off. For us that means that tests logs are complete unusable during to hight amount of tests & changesets. ## Steps To Reproduce Just run the migration. ## Actual Behavior For every change set a message in system out is appeared: ``` Running Changeset: db/changelog/db.changelog-file.xml::version::author ``` ## Expected/Desired Behavior No message in SOUT. A way to completely replace `ConsoleUIService` with `LoggerUIService` so every message could be controlled by logger implementation

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.

veda-tschoening · January 19, 2024, 5:30pm

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

veda-tschoening · January 20, 2024, 5:12pm

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

github.com/liquibase/liquibase

Executed SQL not logged in 4.x versions of Liquibase

opened 08:46AM - 08 Feb 21 UTC

zholub

TypeBug Severity3 ImpactLow Reproduced DBAll IntegrationCLI

## Environment **Liquibase Version**: 4.0.0 or above **Liquibase Integration & V…ersion**: <Pick one: CLI, maven, gradle, spring boot, servlet, etc.> CLI, spring boot **Database Vendor & Version**: Any **Operating System Type & Version**: Any ## Description Liquibase 3.x can log SQL statements executed if logging on `liquibase.executor.jvm.JdbcExecutor` enabled. In 4.x there was a major refactor in commit https://github.com/liquibase/liquibase/commit/3773a7635fcc649d2f1aacf798ed93a0a58bd1e2 It removed explicit logging of SQL statements in favor of `SqlListener`. Now liquibase.executor.jvm.JdbcExecutor barely logs anything. Instead, it could send SQL statements to an SqlListener if specified. Neither I found any documentation about these SqlListeners, nor traces in source code for any uses or public api. The only way i can enable logging is to add an own SqlListener to `Scope.getCurrentScope()` by using reflection. I think Liquibase as a schema evolver tool should have logging capability what it really does with the database. ## Steps To Reproduce Run Liquibase update with root logger set to FINE/TRACE level. ## Actual Behavior No SQL statement show up in log ``` INFO [main] [] liquibase.lockservice - Successfully acquired change log lock INFO [main] [] liquibase.changelog - Reading from SCHEMA.DATABASECHANGELOG ``` ## Expected/Desired Behavior Executed SQL statements show up in log ``` INFO [main] [] liquibase.lockservice - Successfully acquired change log lock DEBUG [main] [] liquibase.sql - SELECT MD5SUM FROM SCHEMA.DATABASECHANGELOG WHERE MD5SUM IS NOT NULL AND ROWNUM=1 DEBUG [main] [] liquibase.sql - SELECT COUNT(*) FROM SCHEMA.DATABASECHANGELOG INFO [main] [] liquibase.changelog - Reading from SCHEMA.DATABASECHANGELOG DEBUG [main] [] liquibase.sql - SELECT * FROM SCHEMA.DATABASECHANGELOG ORDER BY DATEEXECUTED ASC, ORDEREXECUTED ASC ```

daryldoak · January 22, 2024, 2:34pm

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

veda-tschoening · January 22, 2024, 3:59pm

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.

veda-tschoening · January 22, 2024, 6:01pm

I’m finally able to see the SQL! 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.

daryldoak · January 23, 2024, 2:31pm

I’m running the Liquibase CLI via Linux.

Topic		Replies	Views
Liquibase 3.2.2 :: DefaultLogger output to error Liquibase Development	3	467	December 22, 2014
Liquibase 2.0.3 logging with log4j with CustomTaskChange Java code General Discussion	2	764	February 17, 2012
Omit full java stacktrace in mvn-liquibase console output General Discussion	0	129	February 26, 2024
Migration failure : liquibase.exception.DatabaseException: Table 'alert' already exists General Discussion	2	17240	January 27, 2021
Configure liquibase log destination? General Discussion	4	690	January 12, 2011

How to log all generated SQL by Liquibase?

Related Topics