liquibase.exception.LockException: Could not acquire change log lock

spbendekar · September 16, 2022, 3:45pm

We are connecting to MSSQL server DB via GitLab pipeline. I checked DATABASECHANGELOGLOCK table & it shows locked=0

But when we try to apply the changes to the DB, it’s giving error as
liquibase.exception.LockException: Could not acquire change log lock. Currently locked by runner-mftxrtxr-project-28473992-concurrent-0 (172.17.0.3) since 9/15/22, 2:09 AM

Unable to find the runner ID runner-mftxrtxr-project-28473992-concurrent-0 in GitLab logs as well.

We executed below SQL statement but still getting above error
UPDATE DATABASECHANGELOGLOCK SET LOCKED=0, LOCKGRANTED=null, LOCKEDBY=null where ID=1;

Please help and let us know if we are missing anything

tabbyfoo · September 20, 2022, 2:48am

By running the following command:

select * from DATABASECHANGELOGLOCK;

You should be able to check the lockedby column to see who locked the table. Generally, the lock will be from the local machine.

Assuming this is the case (and no other machine has a lock on the database), this should resolve the issue:

Execute the following SQL query against the database:

update DATABASECHANGELOGLOCK
set locked=0, lockgranted=null, lockedby=null
where id=1

Please let us know if you encounter any issues.

EduardUta · September 23, 2022, 12:16pm

Quick question: how is GitLab pipeline configured? Is it by any chance (unintended) running two Liquibase deploys in the same time, over the same target DB ?

Also, could you try unlocking the databasechangeloglock table with the more “official” way, via release-locks command (and then re-try the deploy)? release-locks | Liquibase Docs

Thanks,
Eduard

spbendekar · September 23, 2022, 8:30pm

Thanks for your response, No its executing only one Liquibase instance on target DB.
Yes, now I’ve added extra job to release-lock (irrespective of locks) before execution/update.

EduardUta · September 24, 2022, 5:59am

@spbendekar, did that addressed the issue or it still persists?
(Normally this should not be required, any Liquibase deploy, at the end, automatically releases that lock(for clean setup on next deploy)).

Thanks,
Eduard

Hemu0609 · October 15, 2022, 5:43am

Hi @EduardUta , @tabbyfoo
I am new to liquibase
I want to run the liquibase for cassandra and mysql from one liquibase server, cassandra and mysql are in different servers.
At first it works fine for mysql when I tried with liquibase with cassandra , it stopped working for mysql due to lock.exception and works fine for cassandra .
I tried above solution it did not work.

Below is the error

Unexpected error running Liquibase: Error executing SQL UPDATE Testing.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = ‘’, LOCKGRANTED = 1665812010008 WHERE ID = 1: Data truncation: Incorrect datetime value: ‘1665812009995’ for column ‘LOCKGRANTED’ at row 1

can you please help

EduardUta · October 15, 2022, 8:07am

@Hemu0609 ,

Welcome to Liquibase!
One question:
Are the liquibase calls to the different two RDBMSs (MySQL and Cassandra) made from the same tool/session or different ?
If you can give further details on this setup it would be useful.

Thanks,
Eduard

Hemu0609 · October 15, 2022, 9:05am

@EduardUta Thanks for your help,

Yes, liquibase calls to two different RDBMS’s ( MYSQL and Cassandra ) both are in different VM’s, and I installed Liquibase in another VM, from there only I will communicate to MySQL and Cassandra (installed liquibase in only one VM).

I wrote a script that automate my job , it should first run the MySQL statements and then Cassandra statements.

I tried solutions like

Dropping the table DATABASECHANGELOGLOCK
Deleting the Database
above are not working in my case.

Do i need to have two VM’s for liquibase as well one for MYSQL and one for Cassandra ?

EduardUta · October 15, 2022, 9:31am

Ok, understood, thanks for the extra info!
First of all, one VM for running both deploys should be fine, no need to add another one.
While is still difficult to pinpoint a root cause for this, I would advise to try something:
Run the two deploys in separate sessions (on the same VM). Try to introduce a check in your automatic process and only if first deploy successfully completed start the second one. Should work fine in parallel as well, as long as there are two completely seprate DBs and the deploys are done via independent sessions(but just want to double check that the two deploys are completely independent).
Hope this helps!

Regards,
Eduard

PS: do not recommend dropping the Liquibase tables as a workaround, optionally try to use the unlock command.

Hemu0609 · October 15, 2022, 10:01am

@EduardUta ,

I think they are running as separate sessions , and i tried to release the lock but it is showing that there is no lock on that table DATABASECHANGELOGLOCK.
My automation runs schema one after the another only.

Hemu0609 · October 15, 2022, 10:09am

@EduardUta below log file will help you

liquibase update --log-level=SEVERE
####################################################
##   _     _             _ _                      ##
##  | |   (_)           (_) |                     ##
##  | |    _  __ _ _   _ _| |__   __ _ ___  ___   ##
##  | |   | |/ _` | | | | | '_ \ / _` / __|/ _ \  ##
##  | |___| | (_| | |_| | | |_) | (_| \__ \  __/  ##
##  \_____/_|\__, |\__,_|_|_.__/ \__,_|___/\___|  ##
##              | |                               ##
##              |_|                               ##
##                                                ##
##  Get documentation at docs.liquibase.com       ##
##  Get certified courses at learn.liquibase.com  ##
##  Free schema change activity reports at        ##
##      https://hub.liquibase.com                 ##
##                                                ##
####################################################
Starting Liquibase at 08:06:44 (version 4.15.0 #4001 built at 2022-08-05 16:17+0000)
Liquibase Version: 4.15.0
Liquibase Community 4.15.0 by Liquibase
Loading class `com.mysql.jdbc.Driver'. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver'. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary.
[2022-10-14 08:06:45] SEVERE [liquibase.integration] Error executing SQL UPDATE Testing01.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = '<myhost>', LOCKGRANTED = 1665734805142 WHERE ID = 1: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
liquibase.exception.CommandExecutionException: liquibase.exception.LockException: liquibase.exception.DatabaseException: Error executing SQL UPDATE Testing01.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = '<myhost>', LOCKGRANTED = 1665734805142 WHERE ID = 1: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
	at liquibase.command.CommandScope.execute(CommandScope.java:179)
	at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:51)
	at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:21)
	at picocli.CommandLine.executeUserObject(CommandLine.java:1953)
	at picocli.CommandLine.access$1300(CommandLine.java:145)
	at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2358)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2352)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2314)
	at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2179)
	at picocli.CommandLine$RunLast.execute(CommandLine.java:2316)
	at picocli.CommandLine.execute(CommandLine.java:2078)
	at liquibase.integration.commandline.LiquibaseCommandLine.lambda$execute$1(LiquibaseCommandLine.java:353)
	at liquibase.Scope.child(Scope.java:189)
	at liquibase.Scope.child(Scope.java:165)
	at liquibase.integration.commandline.LiquibaseCommandLine.execute(LiquibaseCommandLine.java:318)
	at liquibase.integration.commandline.LiquibaseCommandLine.main(LiquibaseCommandLine.java:84)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at liquibase.integration.commandline.LiquibaseLauncher.main(LiquibaseLauncher.java:107)
Caused by: liquibase.exception.LockException: liquibase.exception.DatabaseException: Error executing SQL UPDATE Testing01.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = '<myhost>', LOCKGRANTED = 1665734805142 WHERE ID = 1: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
	at liquibase.lockservice.StandardLockService.acquireLock(StandardLockService.java:329)
	at liquibase.lockservice.StandardLockService.waitForLock(StandardLockService.java:247)
	at liquibase.Liquibase.lambda$update$1(Liquibase.java:212)
	at liquibase.Scope.lambda$child$0(Scope.java:180)
	at liquibase.Scope.child(Scope.java:189)
	at liquibase.Scope.child(Scope.java:179)
	at liquibase.Scope.child(Scope.java:158)
	at liquibase.Liquibase.runInScope(Liquibase.java:2414)
	at liquibase.Liquibase.update(Liquibase.java:209)
	at liquibase.Liquibase.update(Liquibase.java:195)
	at liquibase.integration.commandline.Main.doMigration(Main.java:1844)
	at liquibase.integration.commandline.Main$1.lambda$run$0(Main.java:397)
	at liquibase.Scope.lambda$child$0(Scope.java:180)
	at liquibase.Scope.child(Scope.java:189)
	at liquibase.Scope.child(Scope.java:179)
	at liquibase.Scope.child(Scope.java:158)
	at liquibase.integration.commandline.Main$1.run(Main.java:396)
	at liquibase.integration.commandline.Main$1.run(Main.java:218)
	at liquibase.Scope.child(Scope.java:189)
	at liquibase.Scope.child(Scope.java:165)
	at liquibase.integration.commandline.Main.run(Main.java:218)
	at liquibase.command.AbstractCliWrapperCommandStep.run(AbstractCliWrapperCommandStep.java:33)
	at liquibase.command.CommandScope.execute(CommandScope.java:173)
	... 20 more
Caused by: liquibase.exception.DatabaseException: Error executing SQL UPDATE Testing01.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = '<myhost>', LOCKGRANTED = 1665734805142 WHERE ID = 1: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:90)
	at liquibase.executor.jvm.JdbcExecutor.update(JdbcExecutor.java:312)
	at liquibase.executor.jvm.JdbcExecutor.update(JdbcExecutor.java:280)
	at liquibase.lockservice.StandardLockService.acquireLock(StandardLockService.java:297)
	... 42 more
Caused by: com.mysql.cj.jdbc.exceptions.MysqlDataTruncation: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:104)
	at com.mysql.cj.jdbc.StatementImpl.executeUpdateInternal(StatementImpl.java:1334)
	at com.mysql.cj.jdbc.StatementImpl.executeLargeUpdate(StatementImpl.java:2084)
	at com.mysql.cj.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1245)
	at liquibase.executor.jvm.JdbcExecutor$1UpdateStatementCallback.doInStatement(JdbcExecutor.java:303)
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:78)
	... 45 more


Unexpected error running Liquibase: Error executing SQL UPDATE Testing01.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = '<myhost>', LOCKGRANTED = 1665734805142 WHERE ID = 1: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1

liquibase.exception.CommandExecutionException: liquibase.exception.LockException: liquibase.exception.DatabaseException: Error executing SQL UPDATE Testing01.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = '<myhost>', LOCKGRANTED = 1665734805142 WHERE ID = 1: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
	at liquibase.command.CommandScope.execute(CommandScope.java:179)
	at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:51)
	at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:21)
	at picocli.CommandLine.executeUserObject(CommandLine.java:1953)
	at picocli.CommandLine.access$1300(CommandLine.java:145)
	at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2358)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2352)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2314)
	at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2179)
	at picocli.CommandLine$RunLast.execute(CommandLine.java:2316)
	at picocli.CommandLine.execute(CommandLine.java:2078)
	at liquibase.integration.commandline.LiquibaseCommandLine.lambda$execute$1(LiquibaseCommandLine.java:353)
	at liquibase.Scope.child(Scope.java:189)
	at liquibase.Scope.child(Scope.java:165)
	at liquibase.integration.commandline.LiquibaseCommandLine.execute(LiquibaseCommandLine.java:318)
	at liquibase.integration.commandline.LiquibaseCommandLine.main(LiquibaseCommandLine.java:84)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at liquibase.integration.commandline.LiquibaseLauncher.main(LiquibaseLauncher.java:107)
Caused by: liquibase.exception.LockException: liquibase.exception.DatabaseException: Error executing SQL UPDATE Testing01.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = '<myhost>', LOCKGRANTED = 1665734805142 WHERE ID = 1: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
	at liquibase.lockservice.StandardLockService.acquireLock(StandardLockService.java:329)
	at liquibase.lockservice.StandardLockService.waitForLock(StandardLockService.java:247)
	at liquibase.Liquibase.lambda$update$1(Liquibase.java:212)
	at liquibase.Scope.lambda$child$0(Scope.java:180)
	at liquibase.Scope.child(Scope.java:189)
	at liquibase.Scope.child(Scope.java:179)
	at liquibase.Scope.child(Scope.java:158)
	at liquibase.Liquibase.runInScope(Liquibase.java:2414)
	at liquibase.Liquibase.update(Liquibase.java:209)
	at liquibase.Liquibase.update(Liquibase.java:195)
	at liquibase.integration.commandline.Main.doMigration(Main.java:1844)
	at liquibase.integration.commandline.Main$1.lambda$run$0(Main.java:397)
	at liquibase.Scope.lambda$child$0(Scope.java:180)
	at liquibase.Scope.child(Scope.java:189)
	at liquibase.Scope.child(Scope.java:179)
	at liquibase.Scope.child(Scope.java:158)
	at liquibase.integration.commandline.Main$1.run(Main.java:396)
	at liquibase.integration.commandline.Main$1.run(Main.java:218)
	at liquibase.Scope.child(Scope.java:189)
	at liquibase.Scope.child(Scope.java:165)
	at liquibase.integration.commandline.Main.run(Main.java:218)
	at liquibase.command.AbstractCliWrapperCommandStep.run(AbstractCliWrapperCommandStep.java:33)
	at liquibase.command.CommandScope.execute(CommandScope.java:173)
	... 20 more
Caused by: liquibase.exception.DatabaseException: Error executing SQL UPDATE Testing01.DATABASECHANGELOGLOCK SET LOCKED = TRUE, LOCKEDBY = '<myhost>', LOCKGRANTED = 1665734805142 WHERE ID = 1: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:90)
	at liquibase.executor.jvm.JdbcExecutor.update(JdbcExecutor.java:312)
	at liquibase.executor.jvm.JdbcExecutor.update(JdbcExecutor.java:280)
	at liquibase.lockservice.StandardLockService.acquireLock(StandardLockService.java:297)
	... 42 more
Caused by: com.mysql.cj.jdbc.exceptions.MysqlDataTruncation: Data truncation: Incorrect datetime value: '1665734805129' for column 'LOCKGRANTED' at row 1
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:104)
	at com.mysql.cj.jdbc.StatementImpl.executeUpdateInternal(StatementImpl.java:1334)
	at com.mysql.cj.jdbc.StatementImpl.executeLargeUpdate(StatementImpl.java:2084)
	at com.mysql.cj.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1245)
	at liquibase.executor.jvm.JdbcExecutor$1UpdateStatementCallback.doInStatement(JdbcExecutor.java:303)
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:78)
	... 45 more

EduardUta · October 17, 2022, 7:11am

Hmm, interesting.

I am making an assumption here (while not working on the Liquibase product itself nor a “Java guy”):

given your setup, where you are running two liquibase deploys for different RDBMSs (from the same session), I think that at the first runtime (targeting over RDBMS1) the timestamp value to be stored in LOCKGRANTED column might be used for the second execution as well (so also when targeting RDBMS2/MySQL in this erroneous case). So a variable might not get flushed and re-populated there.
Again, just an assumption made.
Another test that you can try (that might confirm / infirm my above theory) is this: try a test (from scratch) with running two deploys one after each other but for the same RDBMS. Then the same (2 deploys for the same RDBMS) for the other one.

Hope this helps, no other ideas atm.
Regards,
Eduard

Hemu0609 · October 18, 2022, 4:22am

@EduardUta
I have two jar in my liquibase lib folders
Cassnadra : CassandraJDBC42.jar
mysql : mysql-connector-java-8.0.30.jar

After deleting atleast one jar then only it is working fine for me.
Liquibase Version: 4.15.0

Topic		Replies	Views
Two processes running Liquibase against the same Db General Discussion	4	950	June 10, 2010
Unexpected error running Liquibase: Error executing SQL UPDATE Liquibase Development	2	1177	October 20, 2022
listUnrunChangeSets throws JDBC error from WaitForLock method Liquibase Development	16	1898	February 12, 2021
Release databasechangeloglock via liquibase api General Discussion	4	804	December 2, 2009
DATABASECHANGELOGLOCK and DATABASECHANGELOG tables Liquibase Development	2	1652	April 1, 2022

liquibase.exception.LockException: Could not acquire change log lock

Related topics