Potential race condition in Raft cluster join process

[deepthidevaki]

Describe the bug
In one cluster two nodes zeebe-0 and zeebe-1 was caught in a loop Attempt to join via 2, Failed to join 2, probably leader but currently not able to accept the join request. Retry later. The leader at this time is zeebe-0. This went for more than an hour. After zeebe-1 was restarted, there was a new election. Then zeebe-1 becomes the leader. The join was completed and both servers started successfully.

D 2020-09-04T06:50:14.288717Z RaftServer{raft-partition-partition-2} - Attempting to join via 2 
D 2020-09-04T06:50:14.288827Z RaftServer{raft-partition-partition-2} - Failed to join 2, probably leader but currently not able to accept the join request. Retry later. 
D 2020-09-04T06:50:14.288899Z RaftServer{raft-partition-partition-2} - Attempting to join via 2 
D 2020-09-04T06:50:14.301364Z RaftServer{raft-partition-partition-2} - Failed to join 2, probably leader but currently not able to accept the join request. Retry later. 
D 2020-09-04T06:50:14.301453Z RaftServer{raft-partition-partition-2} - Failed to join 2, probably leader but currently not able to accept the join request. Retry later. 

2020-09-04 09:00:19.949 CEST
RaftServer{raft-partition-partition-2} - Successfully joined via 2
2020-09-04 09:00:41.926 CEST
RaftServer{raft-partition-partition-2} - Server started successfully!
2020-09-04 09:00:41.926 CEST
Successfully started server for partition PartitionId{id=2, group=raft-partition}

Environment:

• Zeebe Version: stable/0.23

[Zelldon]

I have seen this again in a failing IT tests, which caused bors to fail.

Related build https://ci.zeebe.camunda.cloud/job/zeebe-io/job/zeebe/job/staging/2336/

Output:
output.zip

[Zelldon]

This causes from time to time failing IT tests and it is not really visible in jenkins, since surefire can't open so big xml files.
If you open the normal .txt output files you can see it.

Failed to read test report file /home/jenkins/agent/workspace/_zeebe_5575-remove-documentation/qa/integration-tests/target/surefire-reports/TEST-io.zeebe.broker.it.clustering.RestoreTest-it-testrun.xml
org.dom4j.DocumentException: Error on line 147 of document  : XML document structures must start and end within the same entity.
	at org.dom4j.io.SAXReader.read(SAXReader.java:462)
	at org.dom4j.io.SAXReader.read(SAXReader.java:325)
	at hudson.tasks.junit.SuiteResult.parse(SuiteResult.java:178)
	at hudson.tasks.junit.TestResult.parse(TestResult.java:348)
	at hudson.tasks.junit.TestResult.parsePossiblyEmpty(TestResult.java:281)
	at hudson.tasks.junit.TestResult.parse(TestResult.java:206)
	at hudson.tasks.junit.TestResult.parse(TestResult.java:178)
	at hudson.tasks.junit.TestResult.<init>(TestResult.java:143)
	at hudson.tasks.junit.JUnitParser$ParseResultCallable.invoke(JUnitParser.java:146)
	at hudson.tasks.junit.JUnitParser$ParseResultCallable.invoke(JUnitParser.java:118)
	at hudson.FilePath$FileCallableWrapper.call(FilePath.java:3073)
	at hudson.remoting.UserRequest.perform(UserRequest.java:211)
	at hudson.remoting.UserRequest.perform(UserRequest.java:54)
	at hudson.remoting.Request$2.run(Request.java:369)
	at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:72)
	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 hudson.remoting.Engine$1.lambda$newThread$0(Engine.java:117)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.xml.sax.SAXParseException; lineNumber: 147; columnNumber: 28; XML document structures must start and end within the same entity.
	at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(ErrorHandlerWrapper.java:203)
	at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.fatalError(ErrorHandlerWrapper.java:177)
	at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:400)
	at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:327)
	at com.sun.org.apache.xerces.internal.impl.XMLScanner.reportFatalError(XMLScanner.java:1472)
	at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.endEntity(XMLDocumentFragmentScannerImpl.java:899)
	at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.endEntity(XMLDocumentScannerImpl.java:559)
	at com.sun.org.apache.xerces.internal.impl.XMLEntityManager.endEntity(XMLEntityManager.java:1398)
	at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.load(XMLEntityScanner.java:1916)
	at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.scanData(XMLEntityScanner.java:1375)
	at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanCDATASection(XMLDocumentFragmentScannerImpl.java:1654)
	at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:3014)
	at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:602)
	at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:112)
	at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:505)
	at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:842)
	at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:771)
	at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141)
	at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213)
	at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:643)
	at org.dom4j.io.SAXReader.read(SAXReader.java:445)
	... 19 more

We should fix this.

[Zelldon]

D 2020-10-20T12:59:17.522369Z RaftServer{raft-partition-partition-2} - Failed to join cluster, retrying... 
D 2020-10-20T12:59:17.522886Z RaftServer{raft-partition-partition-2} - Attempting to join via 1 
D 2020-10-20T12:59:17.754511Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:17.755286Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:18.004630Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:18.005589Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:18.254486Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:18.255326Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:18.504561Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:18.505293Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:18.754414Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:18.755339Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:19.005042Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:19.005966Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:19.254334Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:19.255067Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:19.504508Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:19.505387Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:19.754361Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:19.755154Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:20.004673Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:20.005360Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:20.254508Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:20.255371Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:20.504850Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:20.505704Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:20.754494Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:20.755377Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:21.004453Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:21.005609Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:21.254478Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:21.255446Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:21.504950Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:21.505848Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:21.756241Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:21.756995Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:22.004604Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:22.005557Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:22.254171Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:22.254969Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:22.504782Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:22.505545Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:22.523054Z RaftServer{raft-partition-partition-2} - Attempting to join via 0 
D 2020-10-20T12:59:22.754917Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:22.755655Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:23.004868Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:23.005645Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:23.254429Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:23.255253Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:23.504704Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:23.505440Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:23.754335Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:23.755050Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:24.004377Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:24.005098Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:24.254483Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:24.255196Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:24.504667Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:24.505308Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:24.754425Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:24.755266Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:25.004615Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:25.005372Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:25.254618Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:25.255466Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:25.504591Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:25.505305Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:25.754564Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:25.755362Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:26.004747Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:26.005570Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:26.254476Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:26.255367Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:26.504765Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:26.505447Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:26.754641Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:26.755402Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:27.004548Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:27.005742Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:27.254434Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:27.255208Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:27.504432Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:27.505036Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:27.523247Z RaftServer{raft-partition-partition-2} - Failed to join cluster, retrying... 
D 2020-10-20T12:59:27.523687Z RaftServer{raft-partition-partition-2} - Attempting to join via 1 
D 2020-10-20T12:59:27.754556Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:27.755210Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:28.004448Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:28.005078Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:28.254390Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:28.254975Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:28.504611Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:28.505194Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:28.754701Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:28.755304Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:29.004474Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:29.005147Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:29.254649Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:29.255321Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:29.504739Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:29.505461Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:29.754662Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:29.755360Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:30.004609Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:30.005267Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:30.254426Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:30.255065Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:30.504583Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:30.505200Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:30.754403Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:30.754977Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:31.004490Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:31.005394Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:31.254574Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:31.255272Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:31.504437Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:31.505007Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:31.754263Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:31.754916Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:32.004625Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:32.005467Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:32.254458Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:32.255244Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:32.504458Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Received AppendRequest{term=31, leader=1, prevLogIndex=487850673, prevLogTerm=31, entries=0, commitIndex=487850673} 
D 2020-10-20T12:59:32.505194Z RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=31, succeeded=true, lastLogIndex=487850673, lastSnapshotIndex=486726399} 
D 2020-10-20T12:59:32.523847Z RaftServer{raft-partition-partition-2} - Attempting to join via 0 

See in our latest benchmarks it seems that we are not able to join on the leader correctly.

[Zelldon]

I would like to revise the priority. I think this is more problematic then we think. It also causes our builds to fail.

[npepinpe]

As discussed with Deepthi, let's timebox this to reproduce it. If we still can't reproduce it, please do not pick up - however if this happens again and we have a chance to observe it with the additional logs Deepthi added, then let's immediately investigate.

[Zelldon]

I was able to extract the join code into a helper class, such that I can write some unit tests against it.

I was wondering whether this current behavior is really expected. First test:

  @Test
  public void shouldJoin() throws Exception {
    // given
    final var raftMembers = List
        .of(createRaftMemberContext("1"), createRaftMemberContext("2"),
            createRaftMemberContext("3"));
    final CountDownLatch latch = new CountDownLatch(1);
    final var joinResponse = createSuccessfulJoinResponse();
    final var raftJoinHelper = new RaftJoinHelper(singleThreadContext,
        ((memberId, joinRequest) -> CompletableFuture.completedFuture(joinResponse)),
        singleThreadContext::schedule,
        Duration.ofMillis(10), (response) -> latch.countDown());

    // when
    singleThreadContext.execute(() -> {
      raftJoinHelper
          .join(raftMembers.iterator(), () -> createRaftMember("4"), () -> raftMembers.iterator());
    });

    // then
    latch.await(15, TimeUnit.SECONDS);

  }

In the test we pretend that we (local) are node 4 and we want to join 1, 2 and 3. It uses the same code as before it is just has more dependency injection for test ability.

The output is the following:

13:15:26.528 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Attempting to join via 1
13:15:26.535 [] TRACE io.atomix.raft.cluster.impl.RaftJoinHelper - Cancelling join timeout
13:15:26.535 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Attempting to join via 2
13:15:26.535 [] TRACE io.atomix.raft.cluster.impl.RaftJoinHelper - Cancelling join timeout
13:15:26.536 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Successfully joined via 1
13:15:26.536 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Successfully joined via 2

It looks like we immediately try to join two nodes. Is this expected? @npepinpe @deepthidevaki ?

I added another test, where I returned only on one node the successful response.

  @Test
  public void shouldJoinOnlyOneNode() throws Exception {
    // given
    final var raftMembers = List
        .of(createRaftMemberContext("1"), createRaftMemberContext("2"),
            createRaftMemberContext("3"));
    final CountDownLatch latch = new CountDownLatch(1);
    final var joinResponse = createSuccessfulJoinResponse();
    final var noLeaderJoinResponse = createNoLeaderJoinResponse();
    final var raftJoinHelper = new RaftJoinHelper(singleThreadContext,
        ((memberId, joinRequest) -> {
          if (memberId.id().equals("2")) {
            return CompletableFuture.completedFuture(joinResponse);
          }

          return CompletableFuture.completedFuture(noLeaderJoinResponse);
        }),
        singleThreadContext::schedule,
        Duration.ofMillis(10), (response) -> latch.countDown());

    // when
    singleThreadContext.execute(() -> {
      raftJoinHelper
          .join(raftMembers.iterator(), () -> createRaftMember("4"), () -> raftMembers.iterator());
    });

    // then
    latch.await(15, TimeUnit.SECONDS);

  }

And we can see that it tries all until it joined twice?

13:16:46.510 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Attempting to join via 1
13:16:46.518 [] TRACE io.atomix.raft.cluster.impl.RaftJoinHelper - Cancelling join timeout
13:16:46.518 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Attempting to join via 2
13:16:46.519 [] TRACE io.atomix.raft.cluster.impl.RaftJoinHelper - Cancelling join timeout
13:16:46.521 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Failed to join 1. Received error RaftError{type=NO_LEADER, message=null}
13:16:46.521 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Attempting to join via 3
13:16:46.521 [] TRACE io.atomix.raft.cluster.impl.RaftJoinHelper - Cancelling join timeout
13:16:46.522 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Successfully joined via 2
13:16:46.522 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Failed to join 3. Received error RaftError{type=NO_LEADER, message=null}
13:16:46.522 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Failed to join cluster, retrying...
13:16:46.523 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Attempting to join via 1
13:16:46.524 [] TRACE io.atomix.raft.cluster.impl.RaftJoinHelper - Cancelling join timeout
13:16:46.524 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Failed to join 1. Received error RaftError{type=NO_LEADER, message=null}
13:16:46.524 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Attempting to join via 2
13:16:46.524 [] TRACE io.atomix.raft.cluster.impl.RaftJoinHelper - Cancelling join timeout
13:16:46.524 [] DEBUG io.atomix.raft.cluster.impl.RaftJoinHelper - Successfully joined via 2

Process finished with exit code 0

Any thoughts on this? Would like to discuss this before I continue, such that I know what should be the expected behavior.

[npepinpe]

I'm not very familiar with the current implementation, such that it may be "expected" when you read it - but I don't think it's expected behaviour. Been a while since I read the configuration changes section of the paper, but I don't see why it needs to join via 2 nodes. I vaguely remember a section about arbitrary configuration changes which I skimmed - this might be what's implemented in Atomix? There you could add/remove X servers, and not just one at a time, and it might be a bit more complex and require multiple nodes to accept the new config. I'd have to re-read it.

[npepinpe]

Reading more into it, it sounds like we may implement arbitrary configuration changes (which makes sense as we want to restart from a stopped cluster, or start from nothing). Let me read our implementation a bit more and I'll comment again tomorrow morning 👍

How nice it would be to have technical docs ;)

[deepthidevaki]

It does not have to join via all nodes. Only leader can accept a join request. Leader should accept it after the configuration is committed (replicated to quorum). So once the leader sent a successful join response there is no need for it to try to join via other nodes.

[Zelldon]

@deepthidevaki this would be also my thinking. Furthermore I would also expect that it stops the join process, when it becomes leader right?

[Zelldon]

Discussed this topic together with @npepinpe and @deepthidevaki we decided to completely remove the join and leave functionality, since we currently have no benefit out of it.

The join makes sense for dynamic clusters, where we can add nodes later etc. Currently our cluster configurations are static and are known from start on, we don't need to get the knowledge from the leader so there is no need of a join. If we remove the join we should consequently also remove the leave, which is currently also not used by us. If we need that later we can bring it back or implement it in a better way, which is then hopefully more maintainable and less confusing then the current solution.

Furthermore, we checked whether this has consequences on becoming ready if we restart a follower and as far as we saw in the code it should still work as before.

I will create an PR to remove both.