Maybe Race Conditions When Running Concurrently

[SJrX]

This is something I uncovered in my hacky PR #31 , and don't have a test case without it.

With the PR you can simply run (after building)

docker-compose down -v &&  docker-compose up -d mongo && docker-compose up  --build liquibase-cli-1 liquibase-cli-2

You will sometimes get this exception:

liquibase-cli-2_1  | For more information, please use the --logLevel flag
liquibase-cli-2_1  | [2020-08-30 21:17:12] SEVERE [liquibase.integration] Unexpected error running Liquibase: Command failed with error 48 (NamespaceExists): 'Collection already exists. NS: liquibase_cli.databaseChangeLogLock' on server mongo:27017. The full response is {"ok": 0.0, "errmsg": "Collection already exists. NS: liquibase_cli.databaseChangeLogLock", "code": 48, "codeName": "NamespaceExists"}
liquibase-cli-2_1  | liquibase.exception.LockException: com.mongodb.MongoCommandException: Command failed with error 48 (NamespaceExists): 'Collection already exists. NS: liquibase_cli.databaseChangeLogLock' on server mongo:27017. The full response is {"ok": 0.0, "errmsg": "Collection already exists. NS: liquibase_cli.databaseChangeLogLock", "code": 48, "codeName": "NamespaceExists"}
liquibase-cli-2_1  |    at liquibase.ext.mongodb.lockservice.MongoLockService.acquireLock(MongoLockService.java:184)
liquibase-cli-2_1  |    at liquibase.ext.mongodb.lockservice.MongoLockService.waitForLock(MongoLockService.java:121)
liquibase-cli-2_1  |    at liquibase.Liquibase$1.run(Liquibase.java:188)
liquibase-cli-2_1  |    at liquibase.Scope.lambda$child$0(Scope.java:159)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:170)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:158)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:137)
liquibase-cli-2_1  |    at liquibase.Liquibase.runInScope(Liquibase.java:1790)
liquibase-cli-2_1  |    at liquibase.Liquibase.update(Liquibase.java:183)
liquibase-cli-2_1  |    at liquibase.Liquibase.update(Liquibase.java:179)
liquibase-cli-2_1  |    at liquibase.integration.commandline.Main.doMigration(Main.java:1543)
liquibase-cli-2_1  |    at liquibase.integration.commandline.Main$1.lambda$run$0(Main.java:316)
liquibase-cli-2_1  |    at liquibase.Scope.lambda$child$0(Scope.java:159)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:170)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:158)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:137)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:183)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:187)
liquibase-cli-2_1  |    at liquibase.integration.commandline.Main$1.run(Main.java:315)
liquibase-cli-2_1  |    at liquibase.integration.commandline.Main$1.run(Main.java:166)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:170)
liquibase-cli-2_1  |    at liquibase.Scope.child(Scope.java:144)
liquibase-cli-2_1  |    at liquibase.integration.commandline.Main.run(Main.java:166)
liquibase-cli-2_1  |    at liquibase.integration.commandline.Main.main(Main.java:145)
liquibase-cli-2_1  | Caused by: com.mongodb.MongoCommandException: Command failed with error 48 (NamespaceExists): 'Collection already exists. NS: liquibase_cli.databaseChangeLogLock' on server mongo:27017. The full response is {"ok": 0.0, "errmsg": "Collection already exists. NS: liquibase_cli.databaseChangeLogLock", "code": 48, "codeName": "NamespaceExists"}
liquibase-cli-2_1  |    at com.mongodb.internal.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:175)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:303)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:259)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:450)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:226)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
liquibase-cli-2_1  |    at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
liquibase-cli-2_1  |    at com.mongodb.operation.CommandOperationHelper.executeWriteCommand(CommandOperationHelper.java:369)
liquibase-cli-2_1  |    at com.mongodb.operation.CommandOperationHelper.executeWriteCommand(CommandOperationHelper.java:360)
liquibase-cli-2_1  |    at com.mongodb.operation.CommandOperationHelper.executeCommand(CommandOperationHelper.java:284)
liquibase-cli-2_1  |    at com.mongodb.operation.CommandOperationHelper.executeCommand(CommandOperationHelper.java:277)
liquibase-cli-2_1  |    at com.mongodb.operation.CreateCollectionOperation$1.call(CreateCollectionOperation.java:385)
liquibase-cli-2_1  |    at com.mongodb.operation.CreateCollectionOperation$1.call(CreateCollectionOperation.java:381)
liquibase-cli-2_1  |    at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:530)
liquibase-cli-2_1  |    at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:492)
liquibase-cli-2_1  |    at com.mongodb.operation.CreateCollectionOperation.execute(CreateCollectionOperation.java:381)
liquibase-cli-2_1  |    at com.mongodb.operation.CreateCollectionOperation.execute(CreateCollectionOperation.java:57)
liquibase-cli-2_1  |    at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:211)
liquibase-cli-2_1  |    at com.mongodb.client.internal.MongoDatabaseImpl.executeCreateCollection(MongoDatabaseImpl.java:312)
liquibase-cli-2_1  |    at com.mongodb.client.internal.MongoDatabaseImpl.createCollection(MongoDatabaseImpl.java:269)
liquibase-cli-2_1  |    at liquibase.ext.mongodb.statement.CreateCollectionStatement.execute(CreateCollectionStatement.java:90)
liquibase-cli-2_1  |    at liquibase.ext.mongodb.executor.MongoExecutor.execute(MongoExecutor.java:150)
liquibase-cli-2_1  |    at liquibase.ext.mongodb.executor.MongoExecutor.execute(MongoExecutor.java:144)
liquibase-cli-2_1  |    at liquibase.ext.mongodb.lockservice.MongoLockService.init(MongoLockService.java:92)
liquibase-cli-2_1  |    at liquibase.ext.mongodb.lockservice.MongoLockService.acquireLock(MongoLockService.java:154)
liquibase-cli-2_1  |    ... 23 more
liquibase-cli-2_1  | 

I suspect when the databaseChangeLog and databaseChangeLock collections aren't created they two processes fight for creation without using repeatable operations. I'm not sure if my changes caused that error. I did notice in other cases, that two threads can both seemingly think they got the lock although that might be my change shrug.

┆Issue is synchronized with this Jira Bug by Unito

[SJrX]

I think changing this line:

https://github.com/liquibase/liquibase-mongodb/blob/e1e4bfa3865f7125c1c54e748990d88129b83fbd/src/main/java/liquibase/ext/mongodb/lockservice/MongoLockService.java#L97

To:

} catch (DatabaseException | MongoException e) {

Will fix it (although maybe I broke it).

[SJrX]

I also observed that multiple threads can seemingly get the lock, looking at the code:

https://github.com/liquibase/liquibase-mongodb/blob/e1e4bfa3865f7125c1c54e748990d88129b83fbd/src/main/java/liquibase/ext/mongodb/lockservice/ReplaceLockChangeLogStatement.java#L80

I'm not sure I understand how exactly that should work. I might recommend adding a qualifier where locked is false, to see if it is being updated. I'm not sure if that's exactly the issue.

MongoBee has a different approach that I do understand how only one thread can acquire the lock:

https://github.com/mongobee/mongobee/blob/master/src/main/java/com/github/mongobee/dao/LockDao.java#L40