panic: restore failure: database 'test.db' has 1 leader connections

[freeekanayaka]

This crash happens occasionally in the demo program. It happens when a follower has been down long enough to fall behind so much with applied raft logs that the leader no longer has the individual logs that the follower would need to catch up (the amount of trailing logs that a nodes keep is set by the raft.Raft.TrailingLogs parameter). In this case the leader will send to the follower its last snapshot, instead of the individual missing logs, and the follower it restore them using replication.FSM.restoreDatabase(). However restoreDatabase() checks for open leader connection and finds one because the demo code in the follower has already reached the tx, err := db.Begin() line in the insert loop, and is blocked on it.

To reproduce easily, apply a patch like:

modified   raft.go
@@ -39,9 +39,9 @@ func newRaft(config *Config, join string, fsm *replication.FSM, logger *log.Logg
 		MaxAppendEntries:           64,
 		ShutdownOnRemove:           true,
 		DisableBootstrapAfterElect: true,
-		TrailingLogs:               256,
+		TrailingLogs:               10,
 		SnapshotInterval:           500 * time.Millisecond,
-		SnapshotThreshold:          64,
+		SnapshotThreshold:          5,
 		LeaderLeaseTimeout:         config.LeaderLeaseTimeout,
 		EnableSingleNode:           enableSingleNode,
 		Logger:                     logger,

and just stop a follower long enough that it falls behind at least 10 logs. When it restarts, it will crash with the panic reported in the issue title.

Sample output:

10.204.119.242:9980: 2017/07/12 21:32:02 [INFO] demo: start
10.204.119.242:9980: 2017/07/12 21:32:02 [DEBUG] dqlite: restore snapshot
10.204.119.242:9980: 2017/07/12 21:32:02 [DEBUG] dqlite: snapshot database size 385024
10.204.119.242:9980: 2017/07/12 21:32:02 [DEBUG] dqlite: snapshot wal size 391432
10.204.119.242:9980: 2017/07/12 21:32:02 [DEBUG] dqlite: snapshot txid 
10.204.119.242:9980: 2017/07/12 21:32:02 [ERR] sqlite: recovered 95 frames from WAL file
/root/data/test.db-wal (283)
10.204.119.242:9980: 2017/07/12 21:32:02 [INFO] raft: Restored from snapshot
40-2432-1499894688444
10.204.119.242:9980: 2017/07/12 21:32:02 [INFO] raft: Node at 10.204.119.242:9980 [Follower]
entering Follower state (Leader: "")
10.204.119.242:9980: 2017/07/12 21:32:04 [WARN] raft: Heartbeat timeout from "" reached,
starting election
10.204.119.242:9980: 2017/07/12 21:32:04 [INFO] raft: Node at 10.204.119.242:9980
[Candidate] entering Candidate state
10.204.119.242:9980: 2017/07/12 21:32:04 [ERR] raft: Failed to make RequestVote RPC to
10.204.119.99:9980: dialing failed: dial tcp 10.204.119.99:9980: getsockopt: connection
refused
10.204.119.242:9980: 2017/07/12 21:32:04 [ERR] raft: Failed to make RequestVote RPC to
10.204.119.128:9980: dialing failed: dial tcp 10.204.119.128:9980: getsockopt: connection
refused
10.204.119.242:9980: 2017/07/12 21:32:04 [DEBUG] raft: Votes needed: 2
10.204.119.242:9980: 2017/07/12 21:32:04 [DEBUG] raft: Vote granted from
10.204.119.242:9980. Tally: 1
10.204.119.242:9980: 2017/07/12 21:32:06 [WARN] raft: Election timeout reached, restarting
election
10.204.119.242:9980: 2017/07/12 21:32:06 [INFO] raft: Node at 10.204.119.242:9980
[Candidate] entering Candidate state
10.204.119.242:9980: 2017/07/12 21:32:06 [ERR] raft: Failed to make RequestVote RPC to
10.204.119.128:9980: dialing failed: dial tcp 10.204.119.128:9980: getsockopt: connection
refused
10.204.119.242:9980: 2017/07/12 21:32:06 [DEBUG] raft: Votes needed: 2
10.204.119.242:9980: 2017/07/12 21:32:06 [DEBUG] raft: Vote granted from
10.204.119.242:9980. Tally: 1
10.204.119.242:9980: 2017/07/12 21:32:06 [DEBUG] raft-net: 10.204.119.242:9980 accepted
connection from: 10.204.119.99:54206
10.204.119.242:9980: 2017/07/12 21:32:06 [INFO] raft: Node at 10.204.119.242:9980 [Follower]
entering Follower state (Leader: "")
10.204.119.242:9980: 2017/07/12 21:32:06 [WARN] raft: Failed to get previous log: 3218 log
not found (last: 2451)
10.204.119.242:9980: 2017/07/12 21:32:06 [INFO] snapshot: Creating new snapshot at
/root/data/snapshots/42-3215-1499895126707.tmp
10.204.119.242:9980: 2017/07/12 21:32:06 [INFO] snapshot: reaping snapshot
/root/data/snapshots/40-2368-1499894658052
10.204.119.242:9980: 2017/07/12 21:32:06 [INFO] raft: Copied 1068172 bytes to local snapshot
10.204.119.242:9980: 2017/07/12 21:32:06 [DEBUG] dqlite: restore snapshot
10.204.119.242:9980: 2017/07/12 21:32:06 [DEBUG] dqlite: snapshot database size 532480
10.204.119.242:9980: 2017/07/12 21:32:06 [DEBUG] dqlite: snapshot wal size 535632
panic: restore failure: database 'test.db' has 1 leader connections

goroutine 28 [running]:
github.com/dqlite/dqlite/replication.(*FSM).restoreDatabase(0xc42010a900, 0xc9c3a0,
0xc42010d950, 0x0, 0x0, 0x0)
    /root/go/src/github.com/dqlite/dqlite/replication/fsm.go:394 +0x1146
github.com/dqlite/dqlite/replication.(*FSM).Restore(0xc42010a900, 0xc9c3a0, 0xc42010d950,
0xc420123e00, 0xc9c3a0)
    /root/go/src/github.com/dqlite/dqlite/replication/fsm.go:307 +0x84
github.com/hashicorp/raft.(*Raft).runFSM(0xc42013c800)
    /root/go/src/github.com/hashicorp/raft/raft.go:552 +0x383
github.com/hashicorp/raft.(*Raft).(github.com/hashicorp/raft.runFSM)-fm()
    /root/go/src/github.com/hashicorp/raft/raft.go:259 +0x2a
github.com/hashicorp/raft.(*raftState).goFunc.func1(0xc42013c800, 0xc42010ce00)
    /root/go/src/github.com/hashicorp/raft/state.go:142 +0x53
created by github.com/hashicorp/raft.(*raftState).goFunc
    /root/go/src/github.com/hashicorp/raft/state.go:143 +0x66