Liquibase update Command Failing on AWS Keyspaces Due to Lock Table Initialization Error

claudio-oleiro commented 1 week ago

Hi everyone,

I’m encountering an issue while running the liquibase update command on AWS Keyspaces. Based on the debug logs (enabled via liquibase.properties), the problem seems related to the creation/initialization of the lock table. Below are the relevant log details:

[2024-11-24 12:34:08] DETALLADO [liquibase.servicelocator] Loaded liquibase.datatype.LiquibaseDataType instance liquibase.ext.bigquery.datatype.core.NumericDataTypeBigQuery
[2024-11-24 12:34:08] DETALLADO [liquibase.servicelocator] Loaded liquibase.datatype.LiquibaseDataType instance liquibase.ext.bigquery.datatype.core.BignumericDataTypeBigQuery
[2024-11-24 12:34:08] DETALLADO [liquibase.servicelocator] Loaded liquibase.datatype.LiquibaseDataType instance liquibase.ext.cassandra.datatype.CassandraTextDataType
[2024-11-24 12:34:08] DETALLADO [liquibase.executor] DROP TABLE liquibase_test.DATABASECHANGELOGLOCK
[2024-11-24 12:34:09] DETALLADO [liquibase.executor] -1 row(s) affected
[2024-11-24 12:34:09] DETALLADO [liquibase.executor] CREATE TABLE IF NOT EXISTS liquibase_test.DATABASECHANGELOGLOCK (ID INT, LOCKED BOOLEAN, LOCKGRANTED timestamp, LOCKEDBY TEXT, PRIMARY KEY (ID))
[2024-11-24 12:34:09] DETALLADO [liquibase.executor] -1 row(s) affected
[2024-11-24 12:34:09] DETALLADO [liquibase.executor] INSERT INTO liquibase_test.DATABASECHANGELOGLOCK (ID, LOCKED) VALUES (1, FALSE)
[2024-11-24 12:34:09] DETALLADO [liquibase.executor] -1 row(s) affected
[2024-11-24 12:34:09] DETALLADO [liquibase.executor] Changelog query completed.
[2024-11-24 12:34:09] DETALLADO [liquibase.configuration] No configuration value for liquibase.allowDuplicatedChangesetIdentifiers found
[2024-11-24 12:34:09] DETALLADO [liquibase.configuration] Configuration liquibase.allowDuplicatedChangesetIdentifiers is using the default value of false
[2024-11-24 12:34:09] DETALLADO [liquibase.servicelocator] Loaded liquibase.changelog.visitor.ValidatingVisitorGenerator instance liquibase.changelog.visitor.StandardValidatingVisitorGenerator
[2024-11-24 12:34:09] DETALLADO [liquibase.servicelocator] Loaded liquibase.changelog.visitor.ValidatingVisitorGenerator instance com.datical.liquibase.ext.changelog.visitor.ProValidatingVisitorGenerator
[2024-11-24 12:34:09] DETALLADO [liquibase.command] Executing internal command changeExecListener
[2024-11-24 12:34:09] DETALLADO [liquibase.command] Executing internal command update
[2024-11-24 12:34:09] DETALLADO [liquibase.configuration] No configuration value for liquibase.changelogLockWaitTimeInMinutes aka liquibase.changeLogLockWaitTimeInMinutes found
[2024-11-24 12:34:09] DETALLADO [liquibase.configuration] Configuration liquibase.changelogLockWaitTimeInMinutes is using the default value of 5
[2024-11-24 12:34:09] INFORMACIÓN [liquibase.snapshot] Creating snapshot
[2024-11-24 12:34:09] DETALLADO [liquibase.ext] Failed to create or initialize the lock table, trying again, iteration 1 of 10
liquibase.exception.UnexpectedLiquibaseException: liquibase.exception.DatabaseException: java.sql.SQLRecoverableException: Method was called on a closed ResultSet.
    at liquibase.lockservice.StandardLockService.isDatabaseChangeLogLockTableCreated(StandardLockService.java:246)
    at liquibase.lockservice.StandardLockService.init(StandardLockService.java:119)
    at liquibase.ext.cassandra.lockservice.LockServiceCassandra.acquireLock(LockServiceCassandra.java:54)
    at liquibase.lockservice.StandardLockService.waitForLock(StandardLockService.java:262)
    at liquibase.command.core.AbstractUpdateCommandStep.run(AbstractUpdateCommandStep.java:96)
    at liquibase.command.core.UpdateCommandStep.run(UpdateCommandStep.java:100)
    at com.datical.liquibase.ext.command.ProUpdateCommandStep.run(ProUpdateCommandStep.java:45)
    at liquibase.command.CommandScope.lambda$execute$6(CommandScope.java:231)
    at liquibase.Scope.child(Scope.java:203)
    at liquibase.Scope.child(Scope.java:179)
    at liquibase.command.CommandScope.execute(CommandScope.java:219)
    at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:51)
    at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:21)
    at picocli.CommandLine.executeUserObject(CommandLine.java:2045)
    at picocli.CommandLine.access$1500(CommandLine.java:148)
    at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2465)
    at picocli.CommandLine$RunLast.handle(CommandLine.java:2457)
    at picocli.CommandLine$RunLast.handle(CommandLine.java:2419)
    at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2277)
    at picocli.CommandLine$RunLast.execute(CommandLine.java:2421)
    at picocli.CommandLine.execute(CommandLine.java:2174)
    at liquibase.integration.commandline.LiquibaseCommandLine.lambda$execute$2(LiquibaseCommandLine.java:391)
    at liquibase.Scope.child(Scope.java:203)
    at liquibase.Scope.child(Scope.java:179)
    at liquibase.integration.commandline.LiquibaseCommandLine.lambda$execute$3(LiquibaseCommandLine.java:366)
    at liquibase.Scope.child(Scope.java:203)
    at liquibase.Scope.child(Scope.java:179)
    at liquibase.integration.commandline.LiquibaseCommandLine.execute(LiquibaseCommandLine.java:363)
    at liquibase.integration.commandline.LiquibaseCommandLine.main(LiquibaseCommandLine.java:98)
    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)
Caused by: liquibase.exception.DatabaseException: java.sql.SQLRecoverableException: Method was called on a closed ResultSet.
    at liquibase.snapshot.ResultSetCache.get(ResultSetCache.java:100)
    at liquibase.snapshot.JdbcDatabaseSnapshot$CachingDatabaseMetaData.getViews(JdbcDatabaseSnapshot.java:1334)
    at liquibase.snapshot.jvm.ViewSnapshotGenerator.addTo(ViewSnapshotGenerator.java:137)
    at liquibase.snapshot.jvm.JdbcSnapshotGenerator.snapshot(JdbcSnapshotGenerator.java:78)
    at liquibase.snapshot.SnapshotGeneratorChain.snapshot(SnapshotGeneratorChain.java:60)
    at liquibase.snapshot.jvm.JdbcSnapshotGenerator.snapshot(JdbcSnapshotGenerator.java:68)
    at liquibase.snapshot.SnapshotGeneratorChain.snapshot(SnapshotGeneratorChain.java:60)
    at liquibase.snapshot.jvm.JdbcSnapshotGenerator.snapshot(JdbcSnapshotGenerator.java:68)
    at liquibase.snapshot.SnapshotGeneratorChain.snapshot(SnapshotGeneratorChain.java:60)
    at liquibase.snapshot.jvm.JdbcSnapshotGenerator.snapshot(JdbcSnapshotGenerator.java:68)
    at liquibase.snapshot.SnapshotGeneratorChain.snapshot(SnapshotGeneratorChain.java:60)
    at liquibase.snapshot.DatabaseSnapshot.include(DatabaseSnapshot.java:319)
    at liquibase.snapshot.DatabaseSnapshot.init(DatabaseSnapshot.java:112)
    at liquibase.snapshot.DatabaseSnapshot.<init>(DatabaseSnapshot.java:65)
    at liquibase.snapshot.JdbcDatabaseSnapshot.<init>(JdbcDatabaseSnapshot.java:37)
    at liquibase.snapshot.SnapshotGeneratorFactory.createSnapshot(SnapshotGeneratorFactory.java:325)
    at liquibase.snapshot.SnapshotGeneratorFactory.createSnapshot(SnapshotGeneratorFactory.java:298)
    at liquibase.snapshot.SnapshotGeneratorFactory.createSnapshot(SnapshotGeneratorFactory.java:264)
    at liquibase.snapshot.SnapshotGeneratorFactory.createAndCheckSnapshot(SnapshotGeneratorFactory.java:201)
    at liquibase.snapshot.SnapshotGeneratorFactory.checkExistence(SnapshotGeneratorFactory.java:260)
    at liquibase.snapshot.SnapshotGeneratorFactory.has(SnapshotGeneratorFactory.java:220)
    at liquibase.snapshot.SnapshotGeneratorFactory.hasDatabaseChangeLogLockTable(SnapshotGeneratorFactory.java:407)
    at liquibase.lockservice.StandardLockService.isDatabaseChangeLogLockTableCreated(StandardLockService.java:244)
    ... 33 more
Caused by: java.sql.SQLRecoverableException: Method was called on a closed ResultSet.
    at com.ing.data.cassandra.jdbc.CassandraResultSet.checkNotClosed(CassandraResultSet.java:343)
    at com.ing.data.cassandra.jdbc.CassandraResultSet.setFetchSize(CassandraResultSet.java:722)
    at liquibase.snapshot.ResultSetCache$ResultSetExtractor.extract(ResultSetCache.java:288)
    at liquibase.snapshot.ResultSetCache$ResultSetExtractor.extract(ResultSetCache.java:283)
    at liquibase.snapshot.JdbcDatabaseSnapshot$CachingDatabaseMetaData$3.bulkFetchQuery(JdbcDatabaseSnapshot.java:1391)
    at liquibase.snapshot.ResultSetCache$SingleResultSetExtractor.bulkFetch(ResultSetCache.java:343)
    at liquibase.snapshot.ResultSetCache.get(ResultSetCache.java:60)
    ... 55 more
....

After 10 retries, the command terminates with the following error::

[2024-11-24 12:45:21] INFORMACIÓN [liquibase.command] Logging exception.
ERROR: Exception Details
[2024-11-24 12:45:21] INFORMACIÓN [liquibase.ui] ERROR: Exception Details
ERROR: Exception Primary Class:  SQLRecoverableException
[2024-11-24 12:45:21] INFORMACIÓN [liquibase.ui] ERROR: Exception Primary Class:  SQLRecoverableException
ERROR: Exception Primary Reason:  Method was called on a closed ResultSet.
[2024-11-24 12:45:21] INFORMACIÓN [liquibase.ui] ERROR: Exception Primary Reason:  Method was called on a closed ResultSet.
ERROR: Exception Primary Source:  Cassandra 3.11.2
[2024-11-24 12:45:21] INFORMACIÓN [liquibase.ui] ERROR: Exception Primary Source:  Cassandra 3.11.2
[2024-11-24 12:45:21] INFORMACIÓN [liquibase.command] Command execution complete

Observations

The liquibase update command fails during the lock table initialization. After the error, the lock table is deleted (potentially due to Liquibase rollback behavior).
Other commands, like liquibase status and liquibase updateSQL, work without issues.

Current Configuration Here is the relevant liquibase.properties configuration:

changeLogFile=changelog.yaml
classpath=lib/cassandra-jdbc-wrapper-4.13.1-bundle.jar:lib/liquibase-cassandra-4.30.0.jar
log-level=DEBUG
driver: com.ing.data.cassandra.jdbc.CassandraDriver
liquibase.command.url: jdbc:cassandra://cassandra.us-east-1.amazonaws.com:9142/liquibase_test?compliancemode=Liquibase&enablessl=true&localdatacenter=us-east-1&hostnameverification=false&consistency=LOCAL_QUORUM
liquibase.cassandra.awsKeyspacesCompatibilityModeEnabled: true
advanced.heartbeat.interval=30 seconds
advanced.connection.init-query-timeout=30 seconds

changelog file

databaseChangeLog:
  - changeSet:
      id: 1
      author: developer
      changes:
        - createTable:
            tableName: users
            columns:
              - column:
                  name: id
                  type: INT
                  constraints:
                    primaryKey: true
              - column:
                  name: username
                  type: TEXT
              - column:
                  name: email
                  type: TEXT
              - column:
                  name: created_at
                  type: TIMESTAMP

Additional Notes

AWS Keyspaces compatibility mode is enabled (liquibase.cassandra.awsKeyspacesCompatibilityModeEnabled: true).
The error might be related to known limitations or compatibility issues between Liquibase and AWS Keyspaces. However, I couldn’t find any documentation addressing this specific issue.

Steps to Reproduce

Configure Liquibase to connect to AWS Keyspaces using the settings above.
Run the liquibase update command with a basic changelog.

Expected Behavior The liquibase update command should execute successfully, initializing the lock table as needed.

Actual Behavior The command fails during the lock table initialization process, with the error: java.sql.SQLRecoverableException: Method was called on a closed ResultSet.

Request for Assistance Has anyone faced a similar issue or know a workaround to resolve this? Any insights on configuring Liquibase with AWS Keyspaces to handle lock table initialization would be greatly appreciated.

filipelautert commented 3 days ago

@maximevw do you have any idea about it?

claudio-oleiro commented 3 days ago

To provide more context about the issue, I tested the update command using a previous Liquibase version (v4.29.0), and it executed successfully. This suggests that the problem is specific to Liquibase v4.30.0.

maximevw commented 22 hours ago

Hello @claudio-oleiro,

Thank you for the detailed issue. Indeed, I see that in the v4.30.0 of liquibase-standard, the implementation of the method SnapshotGeneratorFactory.has(DatabaseObject, Database) has changed compared to the version 4.29.0. This method is called by the method isDatabaseChangeLogLockTableCreated(boolean) when the StandardLockService is initialized. This method is not re-implemented in the LockServiceCassandra, so a quick fix could be to re-implement it in the LockServiceCassandra re-using the implementation of isDatabaseChangeLogLockTableCreated(): https://github.com/liquibase/liquibase-cassandra/blob/2cbcaf2267e7857b742335101f10e856c363f3b3/src/main/java/liquibase/ext/cassandra/lockservice/LockServiceCassandra.java#L130-L147 This avoid to use the new SnasphotGeneratorFactory implementation, probably not compatible with the constraints of AWS Keyspaces/Cassandra. What do you think @filipelautert?

liquibase / liquibase-cassandra

Liquibase update Command Failing on AWS Keyspaces Due to Lock Table Initialization Error #330