[RATIS-535] Race condition in creating log

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Component/s: LogService
• Assignee: Unassigned
• Reporter: Josh Elser
• Created: 25/Apr/19 19:47
• Updated: 25/Apr/19 19:47

Description

2019-04-25 20:36:27,456 ERROR server.LogStateMachine (VerificationTool.java:waitForCompletion(129)) - Got exception
java.util.concurrent.ExecutionException: java.lang.RuntimeException: org.apache.ratis.logservice.common.LogAlreadyExistException: testlog2
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:192)
at org.apache.ratis.logservice.tool.VerificationTool.waitForCompletion(VerificationTool.java:123)
at org.apache.ratis.logservice.tool.VerificationTool.main(VerificationTool.java:101)
Caused by: java.lang.RuntimeException: org.apache.ratis.logservice.common.LogAlreadyExistException: testlog2
at org.apache.ratis.logservice.tool.VerificationTool$BulkWriter.run(VerificationTool.java:170)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.ratis.logservice.common.LogAlreadyExistException: testlog2
at org.apache.ratis.logservice.server.MetaStateMachine.processCreateLogRequest(MetaStateMachine.java:291)
at org.apache.ratis.logservice.server.MetaStateMachine.query(MetaStateMachine.java:198)
at org.apache.ratis.server.impl.RaftServerImpl.submitClientRequestAsync(RaftServerImpl.java:530)
at org.apache.ratis.server.impl.RaftServerProxy.lambda$submitClientRequestAsync$7(RaftServerProxy.java:333)
at org.apache.ratis.server.impl.RaftServerProxy.lambda$null$5(RaftServerProxy.java:328)
at org.apache.ratis.util.JavaUtils.callAsUnchecked(JavaUtils.java:109)
at org.apache.ratis.server.impl.RaftServerProxy.lambda$submitRequest$6(RaftServerProxy.java:328)
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:981)
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2124)
at org.apache.ratis.server.impl.RaftServerProxy.submitRequest(RaftServerProxy.java:327)
at org.apache.ratis.server.impl.RaftServerProxy.submitClientRequestAsync(RaftServerProxy.java:333)
at org.apache.ratis.grpc.client.GrpcClientProtocolService$RequestStreamObserver.processClientRequest(GrpcClientProtocolService.java:206)
at org.apache.ratis.grpc.client.GrpcClientProtocolService$UnorderedRequestStreamObserver.processClientRequest(GrpcClientProtocolService.java:262)
at org.apache.ratis.grpc.client.GrpcClientProtocolService$RequestStreamObserver.onNext(GrpcClientProtocolService.java:226)
at org.apache.ratis.grpc.client.GrpcClientProtocolService$RequestStreamObserver.onNext(GrpcClientProtocolService.java:154)
at org.apache.ratis.thirdparty.io.grpc.stub.ServerCalls$StreamingServerCallHandler$StreamingServerCallListener.onMessage(ServerCalls.java:248)
at org.apache.ratis.thirdparty.io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailable(ServerCallImpl.java:263)
at org.apache.ratis.thirdparty.io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable.runInContext(ServerImpl.java:686)
at org.apache.ratis.thirdparty.io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at org.apache.ratis.thirdparty.io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
... 3 more

When running the verification tool, I occasionally see the above error message. However, when running the tool, the log definitely did not exist prior:

2019-04-25 20:35:44,278 INFO server.LogStateMachine (VerificationTool.java:main(83)) - Executing parallel writes
2019-04-25 20:35:44,919 INFO server.LogStateMachine (VerificationTool.java:main(91)) - Observed logs already in system: []
2019-04-25 20:35:44,921 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog0']
2019-04-25 20:35:44,932 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog1']
2019-04-25 20:35:44,935 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog3']
2019-04-25 20:35:44,932 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog2']
2019-04-25 20:35:44,941 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog5']
2019-04-25 20:35:44,942 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog4']
2019-04-25 20:35:44,950 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog8']
2019-04-25 20:35:44,948 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog7']
2019-04-25 20:35:44,948 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog6']
2019-04-25 20:35:44,953 INFO server.LogStateMachine (VerificationTool.java:run(157)) - Creating LogName['testlog9']

I don't have a grasp on why this sometimes happens. If I had to guess, I'd start looking around what happens when the leader changes for the metadata quorum.