Race condition for DATABASECHANGELOG table creation for concurrent start of multiple instances
Description
Environment
liquibase-core 3.8.7 (which the "Affected Version" above does not offer), Spring Boot 2.2.5, Oracle XE 18.4
Activity
Show:
Details
Details
Reporter

Components
Affects versions
Priority
Created March 6, 2020 at 2:28 PM
Updated March 6, 2020 at 2:30 PM
We are using Liquibase via the Spring Boot autoconfiguration. While running our CI pipeline we noticed the following race condition while starting multiple instances of the same service against a fresh Oracle schema: The DATABASECHANGELOGLOCK mechanism does not seem to be effective, so that two service instances (service_1 and service_2) concurrently attempt to create the DATABASECHANGELOG table, one of them failing.
The pathological sequence is:
service_1 | {"@timestamp":"2020-03-05T21:43:51.177Z","@version":"1","message":"SELECT COUNT(*) FROM DB_SCHEMA.DATABASECHANGELOGLOCK","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["READ_SQL"]} service_1 | {"@timestamp":"2020-03-05T21:43:51.187Z","@version":"1","message":"SELECT COUNT(*) FROM DB_SCHEMA.DATABASECHANGELOGLOCK","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["READ_SQL"]} service_1 | {"@timestamp":"2020-03-05T21:43:51.200Z","@version":"1","message":"DELETE FROM DB_SCHEMA.DATABASECHANGELOGLOCK","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["WRITE_SQL"]} service_1 | {"@timestamp":"2020-03-05T21:43:51.216Z","@version":"1","message":"INSERT INTO DB_SCHEMA.DATABASECHANGELOGLOCK (ID, LOCKED) VALUES (1, 0)","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["WRITE_SQL"]} service_2 | {"@timestamp":"2020-03-05T21:43:51.268Z","@version":"1","message":"SELECT COUNT(*) FROM DB_SCHEMA.DATABASECHANGELOGLOCK","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["READ_SQL"]} service_2 | {"@timestamp":"2020-03-05T21:43:51.276Z","@version":"1","message":"SELECT COUNT(*) FROM DB_SCHEMA.DATABASECHANGELOGLOCK","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["READ_SQL"]} service_2 | {"@timestamp":"2020-03-05T21:43:51.287Z","@version":"1","message":"DELETE FROM DB_SCHEMA.DATABASECHANGELOGLOCK","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["WRITE_SQL"]} service_1 | {"@timestamp":"2020-03-05T21:43:51.484Z","@version":"1","message":"SELECT LOCKED FROM DB_SCHEMA.DATABASECHANGELOGLOCK WHERE ID=1 FOR UPDATE","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["READ_SQL"]} service_1 | {"@timestamp":"2020-03-05T21:43:51.495Z","@version":"1","message":"Successfully acquired change log lock","logger_name":"liquibase.lockservice.StandardLockService","thread_name":"main","level":"INFO","level_value":20000,"tags":["LOG"]} service_2 | {"@timestamp":"2020-03-05T21:43:51.496Z","@version":"1","message":"INSERT INTO DB_SCHEMA.DATABASECHANGELOGLOCK (ID, LOCKED) VALUES (1, 0)","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["WRITE_SQL"]} service_2 | {"@timestamp":"2020-03-05T21:43:51.500Z","@version":"1","message":"SELECT LOCKED FROM DB_SCHEMA.DATABASECHANGELOGLOCK WHERE ID=1 FOR UPDATE","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["READ_SQL"]} service_2 | {"@timestamp":"2020-03-05T21:43:51.509Z","@version":"1","message":"Successfully acquired change log lock","logger_name":"liquibase.lockservice.StandardLockService","thread_name":"main","level":"INFO","level_value":20000,"tags":["LOG"]} service_1 | {"@timestamp":"2020-03-05T21:43:53.022Z","@version":"1","message":"Creating database history table with name: DB_SCHEMA.DATABASECHANGELOG","logger_name":"liquibase.changelog.StandardChangeLogHistoryService","thread_name":"main","level":"INFO","level_value":20000,"tags":["LOG"]} service_2 | {"@timestamp":"2020-03-05T21:43:53.023Z","@version":"1","message":"Creating database history table with name: DB_SCHEMA.DATABASECHANGELOG","logger_name":"liquibase.changelog.StandardChangeLogHistoryService","thread_name":"main","level":"INFO","level_value":20000,"tags":["LOG"]} service_1 | {"@timestamp":"2020-03-05T21:43:53.024Z","@version":"1","message":"CREATE TABLE DB_SCHEMA.DATABASECHANGELOG (ID VARCHAR2(255) NOT NULL, AUTHOR VARCHAR2(255) NOT NULL, FILENAME VARCHAR2(255) NOT NULL, DATEEXECUTED TIMESTAMP NOT NULL, ORDEREXECUTED INTEGER NOT NULL, EXECTYPE VARCHAR2(10) NOT NULL, MD5SUM VARCHAR2(35), DESCRIPTION VARCHAR2(255), COMMENTS VARCHAR2(255), TAG VARCHAR2(255), LIQUIBASE VARCHAR2(20), CONTEXTS VARCHAR2(255), LABELS VARCHAR2(255), DEPLOYMENT_ID VARCHAR2(10))","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["WRITE_SQL"]} service_2 | {"@timestamp":"2020-03-05T21:43:53.025Z","@version":"1","message":"CREATE TABLE DB_SCHEMA.DATABASECHANGELOG (ID VARCHAR2(255) NOT NULL, AUTHOR VARCHAR2(255) NOT NULL, FILENAME VARCHAR2(255) NOT NULL, DATEEXECUTED TIMESTAMP NOT NULL, ORDEREXECUTED INTEGER NOT NULL, EXECTYPE VARCHAR2(10) NOT NULL, MD5SUM VARCHAR2(35), DESCRIPTION VARCHAR2(255), COMMENTS VARCHAR2(255), TAG VARCHAR2(255), LIQUIBASE VARCHAR2(20), CONTEXTS VARCHAR2(255), LABELS VARCHAR2(255), DEPLOYMENT_ID VARCHAR2(10))","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["WRITE_SQL"]} service_1 | {"@timestamp":"2020-03-05T21:43:53.140Z","@version":"1","message":"SELECT COUNT(*) FROM DB_SCHEMA.DATABASECHANGELOG","logger_name":"liquibase.executor.jvm.JdbcExecutor","thread_name":"main","level":"INFO","level_value":20000,"tags":["READ_SQL"]} service_2 | {"@timestamp":"2020-03-05T21:43:53.143Z","@version":"1","message":"Successfully released change log lock","logger_name":"liquibase.lockservice.StandardLockService","thread_name":"main","level":"INFO","level_value":20000,"tags":["LOG"]} service_2 | {"@timestamp":"2020-03-05T21:43:53.145Z","@version":"1","message":"Error starting Tomcat context. Exception: org.springframework.beans.factory.BeanCreationException. Message: Error creating bean with name 'servletEndpointRegistrar' defined in class path resource [org/springframework/boot/actuate/autoconfigure/endpoint/web/ServletEndpointManagementContextConfiguration$WebMvcServletEndpointManagementContextConfiguration.class]: Bean instantiation via factory method failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [org.springframework.boot.actuate.endpoint.web.ServletEndpointRegistrar]: Factory method 'servletEndpointRegistrar' threw exception; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'healthEndpoint' defined in class path resource [org/springframework/boot/actuate/autoconfigure/health/HealthEndpointConfiguration.class]: Unsatisfied dependency expressed through method 'healthEndpoint' parameter 0; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'healthContributorRegistry' defined in class path resource [org/springframework/boot/actuate/autoconfigure/health/HealthEndpointConfiguration.class]: Bean instantiation via factory method failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [org.springframework.boot.actuate.health.HealthContributorRegistry]: Factory method 'healthContributorRegistry' threw exception; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'remoteRepository' defined in URL [jar:file:/usr/src/app/app.jar!/BOOT-INF/classes!/com/example/ce/kundeninfo/anzeige/model/repository/RemoteRepository.class]: Unsatisfied dependency expressed through constructor parameter 0; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'kmaJpaRepository': Cannot create inner bean '(inner bean)#78c1a023' of type [org.springframework.orm.jpa.SharedEntityManagerCreator] while setting bean property 'entityManager'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name '(inner bean)#78c1a023': Cannot resolve reference to bean 'entityManagerFactory' while setting constructor argument; nested exception is 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.DatabaseException: ORA-00955: name is already used by an existing object\n [Failed SQL: (955) CREATE TABLE DB_SCHEMA.DATABASECHANGELOG (ID VARCHAR2(255) NOT NULL, AUTHOR VARCHAR2(255) NOT NULL, FILENAME VARCHAR2(255) NOT NULL, DATEEXECUTED TIMESTAMP NOT NULL, ORDEREXECUTED INTEGER NOT NULL, EXECTYPE VARCHAR2(10) NOT NULL, MD5SUM VARCHAR2(35), DESCRIPTION VARCHAR2(255), COMMENTS VARCHAR2(255), TAG VARCHAR2(255), LIQUIBASE VARCHAR2(20), CONTEXTS VARCHAR2(255), LABELS VARCHAR2(255), DEPLOYMENT_ID VARCHAR2(10))]","logger_name":"org.springframework.boot.web.embedded.tomcat.TomcatStarter","thread_name":"main","level":"ERROR","level_value":40000}
One can see that two log messages "Successfully acquired change log lock" are emitted before any lock is released (which would be indicated by the log message "Successfully released change log lock").