Postgres 11.10 Liquibase Initialization databasechangeloglock Race Condition

[wnyffenegger]

Environment

Liquibase Version: 3.10.3

Liquibase Integration & Version: spring boot 2.4.0

Liquibase Extension(s) & Version: N/A

Database Vendor & Version: PostgresSQL version 11.10

Operating System Type & Version: Red Hat Enterprise Linux Server release 7.9 (Maipo)

Description

When initializing an environment with a fresh database (common in CI environments) sometimes spring boot applications started concurrently will fail due to an exception creating the databasechangeloglock table.

The logs contain the following messages:

Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException:
Error creating bean with name 'liquibase' defined in class path resource [org/springframework/boot/autoconfigure/liquibase/LiquibaseAutoConfiguration$LiquibaseConfiguration.class]:
Invocation of init method failed; nested exception is liquibase.exception.LockException:
liquibase.exception.UnexpectedLiquibaseException: liquibase.exception.DatabaseException: Error executing SQL SELECT COUNT(*) FROM public.databasechangeloglock:
ERROR: current transaction is aborted, commands ignored until end of transaction
...
common frames omitted\nCaused by: liquibase.exception.DatabaseException: Error executing SQL SELECT COUNT(*) FROM public.databasechangeloglock: ERROR: current transaction is aborted, commands ignored until end of transaction block\n\tat liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:100)\n\tat liquibase.executor.jvm.JdbcExecutor.query(JdbcExecutor.java:173)\n\tat liquibase.executor.jvm.JdbcExecutor.query(JdbcExecutor.java:181)\n\tat liquibase.executor.jvm.JdbcExecutor.queryForObject(JdbcExecutor.java:189)\n\tat liquibase.executor.jvm.JdbcExecutor.queryForObject(JdbcExecutor.java:204)\n\tat liquibase.executor.jvm.JdbcExecutor.queryForInt(JdbcExecutor.java:225)\n\tat liquibase.executor.jvm.JdbcExecutor.queryForInt(JdbcExecutor.java:220)\n\tat liquibase.lockservice.StandardLockService.isDatabaseChangeLogLockTableInitialized(S
tandardLockService.java:168)\n\t... 36 common frames omitted\nCaused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block\n\tat org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)\n\tat org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)\n\tat org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)\n\tat org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)\n\tat org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)\n\tat org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322)\n\tat org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308)\n\tat org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284)\n\tat org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:236)\n\tat com.zaxxer.hikari.pool.ProxyStatement.executeQuery(ProxyStatement.java:111)\n\tat com.zaxxer.hikari.pool

Which eventually leads down to the actual postgres exceptions:

liquibase.executor.jvm.JdbcExecutor$QueryStatementCallback.doInStatement(JdbcExecutor.java:493)
liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:87)... 43 common frames omitted
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint \"pg_type_typname_nsp_index\"\n  Detail: Key (typname, typnamespace)=(databasechangeloglock, 2200) already exists.
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
at ... 

Multiple spring boot applications are attempting to create the databasechangeloglock table at the same time. When this happens occasionally a race condition occurs where one application creates the table (and maybe the lock in the table), then another attempts to create the table and failure ensues.

There is already code in liquibase.lockservice.StandardLockService.init() to catch this exception but either it is not working or another snippet related to handling locks is failing.

Init code snippet

Database Changeloglock Table Initialization Check

Steps To Reproduce

One way to reproduce

This is difficult to reproduce and I do not have an exact script to reproduce it. But theoretically any setup with the following conditions can recreate the issue:

1. Install PostgresSQL 11.10 or start a container with PostgresSQL 11.10
2. Start multiple (the more the better for reproducing the issue) simple SpringBoot applications which need to initialize the databasechangeloglock (even a one change log will work)
3. Repeat until the issue occurs (10 - 20% of the time it occurs with 3 applications)

Second way to reproduce but is not quite the same issue

1. Start postgres fresh locally with an exposed port
2. Open a spring boot application in IntelliJ, Eclipse, VSCode, etc. which uses liquibase 3.10.3
3. Set a break point at StandardLockService.init() specifically at the line executor.comment("Create Database Lock Table");
4. Run the spring boot application in debug mode
5. When the break point is hit insert the databasechangeloglock table manually using PgAdmin, psql, or any other connection.

CREATE TABLE databasechangeloglock(
    id int PRIMARY KEY NOT NULL,
    locked boolean NOT NULL,
    lockgranted TIMESTAMP,
    lockedBy VARCHAR(255)
)

1. Proceed from the break point

Actual Behavior

The result of this error is the failure of SpringBoot applications to start. The applications fail with the following general exception which can be parsed down to the already mentioned exceptions:

Expected/Desired Behavior

To be able to reliably start multiple spring boot applications in parallel which connect and initialize the database for a fresh postgres instance.

Screenshots (if appropriate)

Additional Context

Add any other context about the problem here.

This issue is already addressed in the past here by adding a check of the exception message for exists and ignoring it. For some reason that is not working now.

• https://liquibase.jira.com/browse/CORE-2846
• https://liquibase.jira.com/browse/CORE-2882
• https://liquibase.jira.com/browse/CORE-3125

[molivasdat]

Hi @wnyffenegger Thanks for bringing this issue to our attention. We will add this to the list of issues to process.

[AlexanderMakarov]

Issue is still exists (on PostgreSQL 13.4). Any attempts to resolve it or workarounds?

[kataggart]

@AlexanderMakarov can you please confirm what version of Liquibase you were using when you hit this? Many thanks!

[anton-erofeev]

this issue is still relevant in the 3.10.3 version. Unfortunately I cant migrate to version 4+ right now. Is there any workaround for 3.10.3?

[tacksonfu]

I had the same problem,Is there any workaround for 3.10.3?

[FBurguer]

Im unawere if there is any workaround for 3.10.3. The only thing I can do for now is recomend you to upgrade to our latest version and let us now if the issue still exist there. Thanks