Unit test flake in etcdraft

[tock-ibm]

This use case in the etcdraft suite fails intermittently:

---

• [FAILED] [10.153 seconds] Chain /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:101 3-node Raft cluster /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1565 reconfiguring raft cluster /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1715 reconfiguration /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1823 [It] rotates leader certificate and triggers leadership transfer /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1864

Begin Captured GinkgoWriter Output >> Send artificial MsgTimeoutNow to elect node 1 STEP: Submitting first tx to cut the block 09/05/22 14:17:19.904 STEP: creating new configuration with removed node and new one 09/05/22 14:17:19.921 STEP: sending config transaction 09/05/22 14:17:19.923 << End Captured GinkgoWriter Output

Timed out after 10.001s. Expected : 1 to equal : 2 In [It] at: /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1901

[tock-ibm]

logs_6857.zip Logs

[Param-S]

Another use case failing in the same package with the following stack:

Logs: https://github.com/hyperledger/fabric/actions/runs/3030930972/jobs/4896676060

Chain
/home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:101
  3-node Raft cluster
  /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1565
    reconfiguring raft cluster
    /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1715
      reconfiguration
      /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1823
        [It] removes leader from replica set
        /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:2354

  Begin Captured GinkgoWriter Output >>
    Send artificial MsgTimeoutNow to elect node 1
    STEP: Submitting first tx to cut the block 09/12/22 21:10:15.416
    STEP: sending config transaction 09/12/22 21:10:15.428
  << End Captured GinkgoWriter Output

  Expected a new leader to present
  In [It] at: /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:2393

Analysis:

As per the log statements, the node_1 (leader) initiated the leadership transfer(abdicate leader: https://github.com/hyperledger/fabric/blob/2ef46bbc718de220bbd33ee4e1ce65194b963358/orderer/consensus/etcdraft/node.go#L235), but the node selected for next leadership not accepted the request(https://github.com/hyperledger/fabric/blob/2ef46bbc718de220bbd33ee4e1ce65194b963358/vendor/go.etcd.io/etcd/raft/v3/raft.go#L754), hence the expected leadership not complete.

{"level":"info","msg":"Transferring leadership to 2","channel":"multi-node-channel","node":1} {"level":"info","msg":"1 [term 2] starts to transfer leadership to 2","channel":"multi-node-channel","node":1} {"level":"info","msg":"1 sent MsgTimeoutNow to 2 after received MsgAppResp","channel":"multi-node-channel","node":1}

{"level":"info","msg":"2 [term 2] received MsgTimeoutNow from 1 and starts an election to get leadership.","channel":"multi-node-channel","node":2} {"level":"warn","msg":"2 cannot campaign at term 2 since there are still 1 pending configuration changes to apply","channel":"multi-node-channel","node":2}

Proposed change in testcase:

When the leadership transfer not picked up the next leader, send out artificial MsgTimeOut msg to induce election.

[Param-S]

Analysis:

For the reported failing stack, the use case timed out since a thread/go routine was blocked on leadership change notification condition. The use case is defined to rotate the current leader’s certificate and transfer the leadership to another node. https://github.com/hyperledger/fabric/blob/ad74ff2bc43fd651a2872699c1e9c59733f1e527/orderer/consensus/etcdraft/chain.go#L1302

In this process, every node is defined to wait for the leadership transfer condition to occur before proceeding with the configuration update. https://github.com/hyperledger/fabric/blob/ad74ff2bc43fd651a2872699c1e9c59733f1e527/orderer/consensus/etcdraft/node.go#L282 https://github.com/hyperledger/fabric/blob/ad74ff2bc43fd651a2872699c1e9c59733f1e527/orderer/consensus/etcdraft/chain.go#L1305

Based on the failing log, the thread which was waiting on the notifyc channel was not notified as the other thread well passed the execution before the channel gets established/initialized. Its a race condition between these 2 threads lead to the test case failure.

Updated debug code to observe the failing condition:

func (n *node) abdicateLeader(currentLead uint64) { status := n.Status()

if status.Lead != raft.None && status.Lead != currentLead {
	n.logger.Warn("Leader has changed since asked to transfer leadership")
	return
}

n.logger.Infof("1. Status of raft state machine: %+v", status)

…

timer := n.clock.NewTimer(time.Duration(n.config.ElectionTick) * n.tickInterval)
defer timer.Stop() // prevent timer leak

n.logger.Infof("Awaiting leader transfer notification")
status = n.Status()
n.logger.Infof(“2. Status of raft state machine: %+v", status)

Logs:

{"level":"info","msg":"2 became leader at term 3","channel":"multi-node-channel","node":2} {"level":"info","msg":"raft.node: 2 elected leader 2 at term 3","channel":"multi-node-channel","node":2} {"level":"info","msg":"Raft leader changed: 1 -> 0","channel":"multi-node-channel","node":2} {"level":"info","msg":"Raft leader changed: 0 -> 2","channel":"multi-node-channel","node”:2}. <<<<<<<<< leadership change applied well before the notifyc channel established, hence the run/Ready thread did not send update to that channel

{"level":"info","msg":"1. Status of raft state machine: {"id":"2","term":3,"vote":"2","commit":6,"lead":"0","raftState":"StateCandidate","applied":6,"progress":{},"leadtransferee":"0"}","channel":"multi-node-channel","node":2} {"level":"info","msg":"Awaiting leader transfer notification","channel":"multi-node-channel","node":2} {"level":"info","msg":"2. Status of raft state machine: {"id":"2","term":3,"vote":"2","commit":6,"lead":"2","raftState":"StateLeader","applied":6,"progress":{"1":{"match":0,"next":7,"state":"StateProbe"},"2":{"match":7,"next":8,"state":"StateReplicate"},"3":{"match":0,"next":7,"state":"StateProbe"}},"leadtransferee":"0"}","channel":"multi-node-channel","node":2}

[denyeart]

One set of etcdraft test improvements have been merged. Still a few unit test flakes to resolve in this area though.

[Param-S]

Post PR #3651, few more chain_test flakes noted. One of the scenario is: rotates leader certificate and triggers leadership transfer

https://github.com/hyperledger/fabric/actions/runs/3698440206
https://github.com/hyperledger/fabric/actions/runs/3700821495
------------------------------
• [FAILED] [10.116 seconds]
Chain
/home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:102
  3-node Raft cluster
  /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1580
    reconfiguring raft cluster
    /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1730
      reconfiguration
      /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1838
        [It] rotates leader certificate and triggers leadership transfer
        /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1879

  Begin Captured GinkgoWriter Output >>
    Send artificial MsgTimeoutNow to elect node 1
    STEP: Submitting first tx to cut the block 12/15/22 03:48:14.548
    STEP: creating new configuration with removed node and new one 12/15/22 03:48:14.563
    STEP: sending config transaction 12/15/22 03:48:14.563
  << End Captured GinkgoWriter Output

  Timed out after 10.001s.
  Expected
      <int>: 1
  to equal
      <int>: 2
  In [It] at: /home/runner/work/fabric/fabric/orderer/consensus/etcdraft/chain_test.go:1916

as per the logs, old leader failed to submit the config transaction post abdication as the node chain was not notified/updated on the raft state(leadership) changes.

Failure logs:

{"level":"info","msg":"Start accepting requests as Raft leader at block [1]","channel":"multi-node-channel","node":2}
{"level":"info","msg":"Leader has been transferred from 1 to 2","channel":"multi-node-channel","node":1}
{"level":"info","msg":"abdicateLeader took 8.172946ms","channel":"multi-node-channel","node":1}
{"level":"warn","msg":"Reconfiguration transaction forwarding failed with error: no Raft leader","channel":"multi-node-channel","node":1}
{"level":"info","msg":"Raft leader changed: 0 -> 2","channel":"multi-node-channel","node":1}

I suspect that the state change notification(order of notification) to different go routines from node ready loop causes this condition.

[tock-ibm]

done