search

liquibase / liquibase-cassandra

Liquibase extension for Cassandra Support
Apache License 2.0
47 stars 34 forks source link

Liquibase cannot detect acquired changelog lock. #281

Closed Harduim closed 2 months ago

Harduim commented 2 months ago

This log sequence suggests an issue where a Liquibase operation is trying to acquire a changelog lock but is unable to do so, leading to repeated attempts. 

[2024-04-04 08:21:18] FINE [liquibase.executor] Changelog query completed.
[2024-04-04 08:21:18] FINE [liquibase.executor] Lock Database
[2024-04-04 08:21:18] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-04 08:21:18] FINE [liquibase.configuration] No configuration value for liquibase.changelogLockPollRate aka liquibase.changeLogLockPollRate found
[2024-04-04 08:21:18] FINE [liquibase.configuration] Configuration liquibase.changelogLockPollRate is using the default value of 10
[2024-04-04 08:21:29] FINE [liquibase.executor] Changelog query completed.
[2024-04-04 08:21:29] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-04 08:21:39] FINE [liquibase.executor] Changelog query completed.
[2024-04-04 08:21:39] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-04 08:21:50] FINE [liquibase.executor] Changelog query completed.
[2024-04-04 08:21:50] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-04 08:22:00] FINE [liquibase.executor] Changelog query completed.
[2024-04-04 08:22:00] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-04 08:26:21] FINE [liquibase.executor] Changelog query completed.
[2024-04-04 08:26:21] INFO [liquibase.command] Update command encountered an exception.
[2024-04-04 08:26:21] FINE [liquibase.executor] Release Database Lock
[2024-04-04 08:26:21] INFO [liquibase.ext] Successfully released change log lock
[2024-04-04 08:26:21] WARNING [liquibase.command] Update command encountered exception
liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by UNKNOWN
        at liquibase.lockservice.StandardLockService.waitForLock(StandardLockService.java:285)
        at liquibase.command.core.AbstractUpdateCommandStep.run(AbstractUpdateCommandStep.java:95)
        at liquibase.command.core.UpdateCommandStep.run(UpdateCommandStep.java:105)
        at com.datical.liquibase.ext.command.ProUpdateCommandStep.run(ProUpdateCommandStep.java:42)
        at liquibase.command.CommandScope.execute(CommandScope.java:219)
        at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:55)
        at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:24)
        at picocli.CommandLine.executeUserObject(CommandLine.java:2041)
        at picocli.CommandLine.access$1500(CommandLine.java:148)
        at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2461)
        at picocli.CommandLine$RunLast.handle(CommandLine.java:2453)
        at picocli.CommandLine$RunLast.handle(CommandLine.java:2415)
        at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2273)
        at picocli.CommandLine$RunLast.execute(CommandLine.java:2417)
        at picocli.CommandLine.execute(CommandLine.java:2170)
        at liquibase.integration.commandline.LiquibaseCommandLine.lambda$execute$2(LiquibaseCommandLine.java:395)
        at liquibase.Scope.child(Scope.java:199)
        at liquibase.Scope.child(Scope.java:175)
        at liquibase.integration.commandline.LiquibaseCommandLine.lambda$execute$3(LiquibaseCommandLine.java:370)
        at liquibase.Scope.child(Scope.java:199)
        at liquibase.Scope.child(Scope.java:175)
        at liquibase.integration.commandline.LiquibaseCommandLine.execute(LiquibaseCommandLine.java:367)
        at liquibase.integration.commandline.LiquibaseCommandLine.main(LiquibaseCommandLine.java:104)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at liquibase.integration.commandline.LiquibaseLauncher.main(LiquibaseLauncher.java:116)
Contents of the databasechangeloglock table during the wait: id locked lockedby lockgranted
1 false 2024-04-04 08:21:18.000

If I switch back to version 4.23.2 everything works as expected.

Additional information:

Os version: Ubuntu 22.04 Installation method: Deb package Apache Cassandra tested versions: 4.1.4, 5.0 Extension tested versions: 4.27,4.26,4.25 Liquibase tested versions: 4.27,4.26,4.25

Contents of my liquibase.properties file:

changeLogFile: root-changelog.yml

url: jdbc:cassandra://CASSANDRA_HOST:9042/KEYSPACE_NAME?localdatacenter=localdatacenter&compliancemode=Liquibase;DefaultKeyspace=KEYSPACE_NAME;AuthMech=1;
liquibase.command.username: **************
liquibase.command.password: ****************************

Output of liquibase --version:


SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
####################################################
##   _     _             _ _                      ##
##  | |   (_)           (_) |                     ##
##  | |    _  __ _ _   _ _| |__   __ _ ___  ___   ##
##  | |   | |/ _` | | | | | '_ \ / _` / __|/ _ \  ##
##  | |___| | (_| | |_| | | |_) | (_| \__ \  __/  ##
##  \_____/_|\__, |\__,_|_|_.__/ \__,_|___/\___|  ##
##              | |                               ##
##              |_|                               ##
##                                                ## 
##  Get documentation at docs.liquibase.com       ##
##  Get certified courses at learn.liquibase.com  ## 
##                                                ##
####################################################
Starting Liquibase at 08:28:41 (version 4.27.0 #1525 built at 2024-03-25 17:08+0000)
Liquibase Home: /usr/bin
[picocli WARN] Could not format 'Java Home /home/harduim/.cache/coursier/arc/https/github.com/AdoptOpenJDK/openjdk11-binaries/releases/download/jdk-11%252B28/OpenJDK11-jdk_x64_linux_hotspot_11_28.tar.gz/jdk-11+28 (Version 11)' (Underlying error: Format specifier '%252B'). Using raw String: '%n' format strings have not been replaced with newlines. Please ensure to escape '%' characters with another '%'.
Java Home /home/harduim/.cache/coursier/arc/https/github.com/AdoptOpenJDK/openjdk11-binaries/releases/download/jdk-11%252B28/OpenJDK11-jdk_x64_linux_hotspot_11_28.tar.gz/jdk-11+28 (Version 11)
Libraries:
- internal/lib/commons-collections4.jar: Apache Commons Collections 4.4.0 By The Apache Software Foundation
- internal/lib/commons-lang3.jar: Apache Commons Lang 3.14.0 By The Apache Software Foundation
- internal/lib/commons-text.jar: Apache Commons Text 1.11.0 By The Apache Software Foundation
- internal/lib/h2.jar: H2 Database Engine 2.2.224 By H2 Group
- internal/lib/hsqldb.jar: HSQLDB 2.7.2 By The HSQL Development Group
- internal/lib/jaxb-api.jar: jaxb-api 2.3.1 By Oracle Corporation
- internal/lib/jaxb-core.jar: JAXB Core 4.0.4 By Eclipse Foundation
- internal/lib/jaxb-runtime.jar: JAXB Runtime 4.0.4 By Eclipse Foundation
- internal/lib/jaybird.jar: Jaybird 5.0.3.java8 (build: variant=jaybird tag=v5.0.3 date=202311241106) By Firebird project
- internal/lib/jcc.jar: IBM JCC JDBC 4 Driver 1.4.0 By IBM
- internal/lib/liquibase-commercial.jar: Commercial Liquibase Functionality 4.27.0 By Liquibase
- internal/lib/mariadb-java-client.jar: mariadb-java-client 3.3.3 By mariadb.com
- internal/lib/mssql-jdbc.jar: Microsoft JDBC Driver for SQL Server 12.6.1 By Microsoft Corporation
- internal/lib/ojdbc8.jar: JDBC 19.22.0.0.0 By Oracle Corporation
- internal/lib/opencsv.jar: opencsv 5.9.0
- internal/lib/picocli.jar: picocli 4.7.5 By Remko Popma
- internal/lib/postgresql.jar: PostgreSQL JDBC Driver 42.7.2 By PostgreSQL Global Development Group
- internal/lib/snakeyaml.jar: SnakeYAML 2.2.0
- internal/lib/snowflake-jdbc.jar: snowflake-jdbc 3.14.4
- internal/lib/sqlite-jdbc.jar: SQLite JDBC 3.44.1.0
- lib/CassandraJDBC42.jar: CassandraJDBC42 UNKNOWN
- lib/cassandra-jdbc-wrapper-4.11.1-bundle.jar: cassandra-jdbc-wrapper-4.11.1-bundle UNKNOWN
- lib/liquibase-cassandra-4.27.0.jar: liquibase-cassandra-4.27.0 4.27.0 By Liquibase
maximevw commented 2 months ago

Hello @Harduim

Could you try to remove this part from your JDBC URL: ;DefaultKeyspace=KEYSPACE_NAME;AuthMech=1;? This is related to the Simba driver used until 4.24 and it's useless for ING Cassandra driver used since 4.25. Moreover, as it directly follows the compliancemode parameter, this probably leads to misinterpeting this one and not running with the appropriate behaviour.

Not sure this solves your issue but it clearly might cause other ones.

Harduim commented 2 months ago

Hi @maximevw, thanks for pointing that out!

Unfortunately changing the url to jdbc:cassandra://CASSANDRA_HOST:9042/KEYSPACE_NAME?localdatacenter=localdatacenter&compliancemode=Liquibase; didn't make any difference.

This is the log output after the change:

[2024-04-07 22:16:41] FINE [liquibase.command] Executing internal command changeExecListener
[2024-04-07 22:16:41] FINE [liquibase.command] Executing internal command update
[2024-04-07 22:16:41] FINE [liquibase.configuration] No configuration value for liquibase.changelogLockWaitTimeInMinutes aka liquibase.changeLogLockWaitTimeInMinutes found
[2024-04-07 22:16:41] FINE [liquibase.configuration] Configuration liquibase.changelogLockWaitTimeInMinutes is using the default value of 5
[2024-04-07 22:16:41] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:16:41] FINE [liquibase.executor] Lock Database
[2024-04-07 22:16:41] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:16:41] FINE [liquibase.configuration] No configuration value for liquibase.changelogLockPollRate aka liquibase.changeLogLockPollRate found
[2024-04-07 22:16:41] FINE [liquibase.configuration] Configuration liquibase.changelogLockPollRate is using the default value of 10
[2024-04-07 22:16:52] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:16:52] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:17:02] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:17:03] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:17:13] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:17:13] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:17:24] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:17:24] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:17:34] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:17:34] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:17:45] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:17:45] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:17:55] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:17:56] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:18:06] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:18:06] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:18:17] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:18:17] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:18:27] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:18:28] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:18:38] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:18:38] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:18:49] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:18:49] INFO [liquibase.ext] Waiting for changelog lock....
[2024-04-07 22:18:59] FINE [liquibase.executor] Changelog query completed.
[2024-04-07 22:19:00] INFO [liquibase.ext] Waiting for changelog lock....

Here is the content of the databasechangeloglock during the wait.

id locked lockedby lockgranted
1 true ideiapadg3 (****) 2024-04-07 22:16:41.000

Thanks for your help.

maximevw commented 2 months ago

@Harduim, You must also remove the semicolon after Liquibase. The parameter separator is & for ING driver and consequently, here it tries to apply an unexistant Liquibase; compliance mode and so fallbacks to the default driver behaviour causing known issues when running in Liquibase.

The error message is very similar to issue #249 but the cause is certainly different here. 🤔

Harduim commented 2 months ago

@maximevw thanks for the help, that worked!