Bug report: Log indexing logic

[caleb-fringer]

I encountered the following issue while trying to debug the client Create message:

In the leader (node 2)'s logs, this is what happened:

2025/11/27 22:28:28 Log index logic error: provided index lies below first actual entry of log
panic: Log index logic error: provided index lies below first actual entry of log

goroutine 30 [running]:
log.Panicf({0x9ad94a?, 0xc000191b40?}, {0xc000191e80?, 0x0?, 0x40b345?})
        /usr/local/go/src/log/log.go:460 +0x74
github.com/djsurt/monkey-minder/server/internal/raft.(*RaftServer).doLeader(0xc000158180, {0xa62870, 0xc0001709b0})
        /home/caleb/src/github.com/caleb-fringer/monkey-minder/server/internal/raft/leader.go:153 +0x1437
github.com/djsurt/monkey-minder/server/internal/raft.(*RaftServer).doLoop(0xc000158180, {0xa62870, 0xc0001709b0})
        /home/caleb/src/github.com/caleb-fringer/monkey-minder/server/internal/raft/server.go:101 +0x37
created by github.com/djsurt/monkey-minder/server/internal/raft.(*RaftServer).Serve in goroutine 1
        /home/caleb/src/github.com/caleb-fringer/monkey-minder/server/internal/raft/server.go:154 +0x285
exit status 2

Steps that occurred:

1. Started up node 2
2. Started up node 3
3. Node 2 gets elected leader
4. Node 2 performs the initialization section which includes writting /foo to the log
5. Node 2 sends out initial AE messages to nodes 1 & 3
6. Node 3 receives the following AE entry: 2025/11/27 22:28:28 incoming AE: term:2 leaderId:2 entries:{term:2 targetPath:"/foo" value:"<initial value>"}
7. Node 3 responds w/ matchIdx, nextIdx (1,2)
8. Start up node 1 in debugging mode w/ breakpoint at line 76 of server/internal/raft/clientsession.go (server.Send(resp)) (I doubt this happens before the failure occurs as its in another tab)
9. Node 3 sets smallestMajorityIdx to 0
10. Node 3 checks to see if it has a log entry at 0, which fails.
11. Node 3 moves on from the AE response processing loop
12. Node 3 reads from the doAESend chan
13. Node 3 reads one of the peer's nextIndex, which must have been 0 according to the log failure.
14. While iterating over idx := toSendFirst (which is the peer's next index) to idx < s.log.IndexAfterLast() (which would have been 2), node 3 performs s.log.GetEntryAt(idx), which errors with provided index lies below first actual entry of log indicating it tried to retrieve a value of 0

I've tried reproducing without success by starting node 2, waiting for it to enter election, then starting node 3 without starting node 1.

Here's the log for node 3:

Raft server listening on port 9003...
2025/11/27 22:28:28 Vote request received from 2
2025/11/27 22:28:28 VOTE: My Term: 2, Candidate's Term: 2
2025/11/27 22:28:28 Granting vote to CANDIDATE 2
2025/11/27 22:28:28 incoming AE: term:2  leaderId:2  entries:{term:2  targetPath:"/foo"  value:"<initial value>"}
2025/11/27 22:28:28 Value of prevLogIdx: 0
2025/11/27 22:28:28 Vote request received from 1
2025/11/27 22:28:28 VOTE: My Term: 4, Candidate's Term: 4
2025/11/27 22:28:30 Vote request received from 1
2025/11/27 22:28:30 VOTE: My Term: 5, Candidate's Term: 5
2025/11/27 22:28:31 Election timeout occurred. Switching to CANDIDATE state
2025/11/27 22:28:31 Error requesting vote from node 2: Node unavailable
2025/11/27 22:28:31 Vote received from node 1
2025/11/27 22:28:31 Vote count: 1
2025/11/27 22:28:31 Asserting myself as LEADER.
2025/11/27 22:28:31 A
2025/11/27 22:28:31 B
2025/11/27 22:28:31 Log length: 1
2025/11/27 22:28:31 Node 1 (matchIdx, nextIdx): (1, 2)
2025/11/27 22:28:31 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:32 Log length: 1
2025/11/27 22:28:32 Node 1 (matchIdx, nextIdx): (1, 2)
2025/11/27 22:28:32 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:33 Log length: 1
2025/11/27 22:28:33 Node 1 (matchIdx, nextIdx): (1, 2)
2025/11/27 22:28:33 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:34 Log length: 1
2025/11/27 22:28:34 Node 1 (matchIdx, nextIdx): (1, 2)
2025/11/27 22:28:34 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:34 Log length: 1
2025/11/27 22:28:34 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:34 Node 1 (matchIdx, nextIdx): (1, 2)
2025/11/27 22:28:35 Log length: 1
2025/11/27 22:28:35 Node 1 (matchIdx, nextIdx): (1, 2)
2025/11/27 22:28:35 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:36 Log length: 1
2025/11/27 22:28:36 Node 1 (matchIdx, nextIdx): (1, 2)
2025/11/27 22:28:36 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:37 Log length: 2
2025/11/27 22:28:37 Node 1 (matchIdx, nextIdx): (2, 3)
2025/11/27 22:28:37 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:37 Log length: 2
2025/11/27 22:28:37 Node 1 (matchIdx, nextIdx): (2, 3)
2025/11/27 22:28:37 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:38 Log length: 2
2025/11/27 22:28:38 Node 1 (matchIdx, nextIdx): (2, 3)
2025/11/27 22:28:38 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:39 Log length: 2
2025/11/27 22:28:39 Node 1 (matchIdx, nextIdx): (2, 3)
2025/11/27 22:28:39 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:40 Log length: 2
2025/11/27 22:28:40 Node 1 (matchIdx, nextIdx): (2, 3)
2025/11/27 22:28:40 Node 2 (matchIdx, nextIdx): (0, 2)
2025/11/27 22:28:40 Log length: 2
2025/11/27 22:28:40 Node 1 (matchIdx, nextIdx): (2, 3)
2025/11/27 22:28:40 Node 2 (matchIdx, nextIdx): (0, 2)
^Csignal: interrupt

And node 2:

Raft server listening on port 9002...
2025/11/27 22:28:28 Election timeout occurred. Switching to CANDIDATE state
2025/11/27 22:28:28 Vote received from node 3
2025/11/27 22:28:28 Vote count: 1
2025/11/27 22:28:28 Asserting myself as LEADER.
2025/11/27 22:28:28 A
2025/11/27 22:28:28 B
2025/11/27 22:28:28 Log length: 1
2025/11/27 22:28:28 Node 3 (matchIdx, nextIdx): (1, 2)
2025/11/27 22:28:28 Node 1 (matchIdx, nextIdx): (0, 1)
2025/11/27 22:28:28 Log index logic error: provided index lies below first actual entry of log
panic: Log index logic error: provided index lies below first actual entry of log

goroutine 30 [running]:
log.Panicf({0x9ad94a?, 0xc000191b40?}, {0xc000191e80?, 0x0?, 0x40b345?})
        /usr/local/go/src/log/log.go:460 +0x74
github.com/djsurt/monkey-minder/server/internal/raft.(*RaftServer).doLeader(0xc000158180, {0xa62870, 0xc0001709b0})
        /home/caleb/src/github.com/caleb-fringer/monkey-minder/server/internal/raft/leader.go:153 +0x1437
github.com/djsurt/monkey-minder/server/internal/raft.(*RaftServer).doLoop(0xc000158180, {0xa62870, 0xc0001709b0})
        /home/caleb/src/github.com/caleb-fringer/monkey-minder/server/internal/raft/server.go:101 +0x37
created by github.com/djsurt/monkey-minder/server/internal/raft.(*RaftServer).Serve in goroutine 1
        /home/caleb/src/github.com/caleb-fringer/monkey-minder/server/internal/raft/server.go:154 +0x285
exit status 2