Skip to content

Commit

Permalink
tracker: add commit index to debug output
Browse files Browse the repository at this point in the history
Signed-off-by: Pavel Kalinnikov <[email protected]>
  • Loading branch information
pav-kv committed Jan 24, 2024
1 parent 4984110 commit c9ea2f0
Show file tree
Hide file tree
Showing 12 changed files with 76 additions and 75 deletions.
2 changes: 1 addition & 1 deletion testdata/campaign_learner_must_vote.txt
Original file line number Diff line number Diff line change
Expand Up @@ -113,7 +113,7 @@ stabilize 2 3
> 2 receiving messages
3->2 MsgAppResp Term:2 Log:1/4 Rejected (Hint: 3)
DEBUG 2 received MsgAppResp(rejected, hint: (index 3, term 1)) from 3 for index 4
DEBUG 2 decreased progress of 3 to [StateProbe match=0 next=4]
DEBUG 2 decreased progress of 3 to [StateProbe match=0 commit=0 next=4]
> 2 handling Ready
Ready MustSync=false:
Messages:
Expand Down
8 changes: 4 additions & 4 deletions testdata/confchange_v1_add_single.txt
Original file line number Diff line number Diff line change
Expand Up @@ -70,9 +70,9 @@ stabilize
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/3 Rejected (Hint: 0)
DEBUG 1 received MsgAppResp(rejected, hint: (index 0, term 0)) from 2 for index 3
DEBUG 1 decreased progress of 2 to [StateProbe match=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 next=1 paused pendingSnap=4]
DEBUG 1 decreased progress of 2 to [StateProbe match=0 commit=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 commit=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 commit=0 next=1 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand All @@ -91,7 +91,7 @@ stabilize
2->1 MsgAppResp Term:1 Log:0/4
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/4
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 next=5 paused pendingSnap=4]
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 commit=0 next=5 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand Down
16 changes: 8 additions & 8 deletions testdata/confchange_v2_add_double_auto.txt
Original file line number Diff line number Diff line change
Expand Up @@ -93,9 +93,9 @@ stabilize 1 2
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/3 Rejected (Hint: 0)
DEBUG 1 received MsgAppResp(rejected, hint: (index 0, term 0)) from 2 for index 3
DEBUG 1 decreased progress of 2 to [StateProbe match=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 next=1 paused pendingSnap=4]
DEBUG 1 decreased progress of 2 to [StateProbe match=0 commit=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 commit=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 commit=0 next=1 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand All @@ -114,7 +114,7 @@ stabilize 1 2
2->1 MsgAppResp Term:1 Log:0/4
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/4
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 next=5 paused pendingSnap=4]
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 commit=0 next=5 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand Down Expand Up @@ -167,9 +167,9 @@ stabilize 1 3
> 1 receiving messages
3->1 MsgAppResp Term:1 Log:0/3 Rejected (Hint: 0)
DEBUG 1 received MsgAppResp(rejected, hint: (index 0, term 0)) from 3 for index 3
DEBUG 1 decreased progress of 3 to [StateProbe match=0 next=1]
DEBUG 1 [firstindex: 3, commit: 5] sent snapshot[index: 5, term: 1] to 3 [StateProbe match=0 next=1]
DEBUG 1 paused sending replication messages to 3 [StateSnapshot match=0 next=1 paused pendingSnap=5]
DEBUG 1 decreased progress of 3 to [StateProbe match=0 commit=0 next=1]
DEBUG 1 [firstindex: 3, commit: 5] sent snapshot[index: 5, term: 1] to 3 [StateProbe match=0 commit=0 next=1]
DEBUG 1 paused sending replication messages to 3 [StateSnapshot match=0 commit=0 next=1 paused pendingSnap=5]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand All @@ -188,7 +188,7 @@ stabilize 1 3
3->1 MsgAppResp Term:1 Log:0/5
> 1 receiving messages
3->1 MsgAppResp Term:1 Log:0/5
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 3 [StateSnapshot match=5 next=6 paused pendingSnap=5]
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 3 [StateSnapshot match=5 commit=0 next=6 paused pendingSnap=5]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand Down
8 changes: 4 additions & 4 deletions testdata/confchange_v2_add_double_implicit.txt
Original file line number Diff line number Diff line change
Expand Up @@ -76,9 +76,9 @@ stabilize 1 2
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/3 Rejected (Hint: 0)
DEBUG 1 received MsgAppResp(rejected, hint: (index 0, term 0)) from 2 for index 3
DEBUG 1 decreased progress of 2 to [StateProbe match=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 next=1 paused pendingSnap=4]
DEBUG 1 decreased progress of 2 to [StateProbe match=0 commit=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 commit=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 commit=0 next=1 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand All @@ -97,7 +97,7 @@ stabilize 1 2
2->1 MsgAppResp Term:1 Log:0/4
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/4
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 next=5 paused pendingSnap=4]
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 commit=0 next=5 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand Down
8 changes: 4 additions & 4 deletions testdata/confchange_v2_add_single_auto.txt
Original file line number Diff line number Diff line change
Expand Up @@ -71,9 +71,9 @@ stabilize
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/3 Rejected (Hint: 0)
DEBUG 1 received MsgAppResp(rejected, hint: (index 0, term 0)) from 2 for index 3
DEBUG 1 decreased progress of 2 to [StateProbe match=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 next=1 paused pendingSnap=4]
DEBUG 1 decreased progress of 2 to [StateProbe match=0 commit=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 commit=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 commit=0 next=1 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand All @@ -92,7 +92,7 @@ stabilize
2->1 MsgAppResp Term:1 Log:0/4
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/4
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 next=5 paused pendingSnap=4]
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 commit=0 next=5 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand Down
8 changes: 4 additions & 4 deletions testdata/confchange_v2_add_single_explicit.txt
Original file line number Diff line number Diff line change
Expand Up @@ -71,9 +71,9 @@ stabilize 1 2
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/3 Rejected (Hint: 0)
DEBUG 1 received MsgAppResp(rejected, hint: (index 0, term 0)) from 2 for index 3
DEBUG 1 decreased progress of 2 to [StateProbe match=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 next=1 paused pendingSnap=4]
DEBUG 1 decreased progress of 2 to [StateProbe match=0 commit=0 next=1]
DEBUG 1 [firstindex: 3, commit: 4] sent snapshot[index: 4, term: 1] to 2 [StateProbe match=0 commit=0 next=1]
DEBUG 1 paused sending replication messages to 2 [StateSnapshot match=0 commit=0 next=1 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand All @@ -92,7 +92,7 @@ stabilize 1 2
2->1 MsgAppResp Term:1 Log:0/4
> 1 receiving messages
2->1 MsgAppResp Term:1 Log:0/4
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 next=5 paused pendingSnap=4]
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 2 [StateSnapshot match=4 commit=0 next=5 paused pendingSnap=4]
> 1 handling Ready
Ready MustSync=false:
Messages:
Expand Down
20 changes: 10 additions & 10 deletions testdata/heartbeat_resp_recovers_from_probing.txt
Original file line number Diff line number Diff line change
Expand Up @@ -28,20 +28,20 @@ ok

status 1
----
1: StateReplicate match=11 next=12
2: StateReplicate match=11 next=12
3: StateReplicate match=11 next=12
1: StateReplicate match=11 commit=10 next=12
2: StateReplicate match=11 commit=11 next=12
3: StateReplicate match=11 commit=11 next=12

# On the first replica, report the second one as not reachable.
report-unreachable 1 2
----
DEBUG 1 failed to send message to 2 because it is unreachable [StateProbe match=11 next=12]
DEBUG 1 failed to send message to 2 because it is unreachable [StateProbe match=11 commit=11 next=12]

status 1
----
1: StateReplicate match=11 next=12
2: StateProbe match=11 next=12
3: StateReplicate match=11 next=12
1: StateReplicate match=11 commit=10 next=12
2: StateProbe match=11 commit=11 next=12
3: StateReplicate match=11 commit=11 next=12

tick-heartbeat 1
----
Expand Down Expand Up @@ -85,6 +85,6 @@ stabilize

status 1
----
1: StateReplicate match=11 next=12
2: StateReplicate match=11 next=12
3: StateReplicate match=11 next=12
1: StateReplicate match=11 commit=10 next=12
2: StateReplicate match=11 commit=11 next=12
3: StateReplicate match=11 commit=11 next=12
30 changes: 15 additions & 15 deletions testdata/replicate_pause.txt
Original file line number Diff line number Diff line change
Expand Up @@ -46,9 +46,9 @@ ok
# Expect that in-flight tracking to nodes 2 and 3 is saturated.
status 1
----
1: StateReplicate match=14 next=15
2: StateReplicate match=11 next=15 paused inflight=3[full]
3: StateReplicate match=11 next=15 paused inflight=3[full]
1: StateReplicate match=14 commit=11 next=15
2: StateReplicate match=11 commit=11 next=15 paused inflight=3[full]
3: StateReplicate match=11 commit=11 next=15 paused inflight=3[full]

log-level none
----
Expand All @@ -66,9 +66,9 @@ ok
# Expect that the entries are committed and stored on nodes 1 and 2.
status 1
----
1: StateReplicate match=14 next=15
2: StateReplicate match=14 next=15
3: StateReplicate match=11 next=15 paused inflight=3[full]
1: StateReplicate match=14 commit=11 next=15
2: StateReplicate match=14 commit=14 next=15
3: StateReplicate match=11 commit=11 next=15 paused inflight=3[full]

# Drop append messages to node 3.
deliver-msgs drop=3
Expand All @@ -94,9 +94,9 @@ ok
# In-flight tracking to nodes 2 and 3 is saturated, but node 3 is behind.
status 1
----
1: StateReplicate match=14 next=15
2: StateReplicate match=14 next=18 paused inflight=3[full]
3: StateReplicate match=11 next=15 paused inflight=3[full]
1: StateReplicate match=14 commit=11 next=15
2: StateReplicate match=14 commit=14 next=18 paused inflight=3[full]
3: StateReplicate match=11 commit=11 next=15 paused inflight=3[full]

log-level none
----
Expand All @@ -114,9 +114,9 @@ ok
# Expect that the entries are committed and stored only on nodes 1 and 2.
status 1
----
1: StateReplicate match=17 next=18
2: StateReplicate match=17 next=18
3: StateReplicate match=11 next=15 paused inflight=3[full]
1: StateReplicate match=17 commit=14 next=18
2: StateReplicate match=17 commit=17 next=18
3: StateReplicate match=11 commit=11 next=15 paused inflight=3[full]

# Make a heartbeat roundtrip.
tick-heartbeat 1
Expand Down Expand Up @@ -185,6 +185,6 @@ ok
# Eventually all nodes catch up on the committed state.
status 1
----
1: StateReplicate match=17 next=18
2: StateReplicate match=17 next=18
3: StateReplicate match=17 next=18
1: StateReplicate match=17 commit=14 next=18
2: StateReplicate match=17 commit=17 next=18
3: StateReplicate match=17 commit=17 next=18
18 changes: 9 additions & 9 deletions testdata/slow_follower_after_compaction.txt
Original file line number Diff line number Diff line change
Expand Up @@ -43,9 +43,9 @@ ok
# All nodes up-to-date.
status 1
----
1: StateReplicate match=14 next=15
2: StateReplicate match=14 next=15
3: StateReplicate match=14 next=15
1: StateReplicate match=14 commit=11 next=15
2: StateReplicate match=14 commit=14 next=15
3: StateReplicate match=14 commit=14 next=15

log-level none
----
Expand Down Expand Up @@ -79,9 +79,9 @@ ok
# Nodes 1 and 2 up-to-date, 3 is behind and MsgApp flow is throttled.
status 1
----
1: StateReplicate match=18 next=19
2: StateReplicate match=18 next=19
3: StateReplicate match=14 next=17 paused inflight=2[full]
1: StateReplicate match=18 commit=14 next=19
2: StateReplicate match=18 commit=18 next=19
3: StateReplicate match=14 commit=14 next=17 paused inflight=2[full]

# Break the MsgApp flow from the leader to node 3.
deliver-msgs drop=3
Expand Down Expand Up @@ -116,6 +116,6 @@ ok
# All nodes caught up.
status 1
----
1: StateReplicate match=18 next=19
2: StateReplicate match=18 next=19
3: StateReplicate match=18 next=19
1: StateReplicate match=18 commit=14 next=19
2: StateReplicate match=18 commit=18 next=19
3: StateReplicate match=18 commit=18 next=19
24 changes: 12 additions & 12 deletions testdata/snapshot_succeed_via_app_resp.txt
Original file line number Diff line number Diff line change
Expand Up @@ -41,9 +41,9 @@ ok

status 1
----
1: StateReplicate match=11 next=12
2: StateReplicate match=11 next=12
3: StateProbe match=0 next=11 paused inactive
1: StateReplicate match=11 commit=10 next=12
2: StateReplicate match=11 commit=11 next=12
3: StateProbe match=0 commit=0 next=11 paused inactive

# Add the node that will receive a snapshot (it has no state at all, does not
# even have a config).
Expand Down Expand Up @@ -86,18 +86,18 @@ stabilize 1
----
> 1 receiving messages
3->1 MsgHeartbeatResp Term:1 Log:0/0
DEBUG 1 [firstindex: 12, commit: 11] sent snapshot[index: 11, term: 1] to 3 [StateProbe match=0 next=11]
DEBUG 1 paused sending replication messages to 3 [StateSnapshot match=0 next=11 paused pendingSnap=11]
DEBUG 1 [firstindex: 12, commit: 11] sent snapshot[index: 11, term: 1] to 3 [StateProbe match=0 commit=0 next=11]
DEBUG 1 paused sending replication messages to 3 [StateSnapshot match=0 commit=0 next=11 paused pendingSnap=11]
> 1 handling Ready
Ready MustSync=false:
Messages:
1->3 MsgSnap Term:1 Log:0/0 Snapshot: Index:11 Term:1 ConfState:Voters:[1 2 3] VotersOutgoing:[] Learners:[] LearnersNext:[] AutoLeave:false

status 1
----
1: StateReplicate match=11 next=12
2: StateReplicate match=11 next=12
3: StateSnapshot match=0 next=11 paused pendingSnap=11
1: StateReplicate match=11 commit=10 next=12
2: StateReplicate match=11 commit=11 next=12
3: StateSnapshot match=0 commit=0 next=11 paused pendingSnap=11

# Follower applies the snapshot. Note how it reacts with a MsgAppResp upon completion.
# The snapshot fully catches the follower up (i.e. there are no more log entries it
Expand All @@ -124,17 +124,17 @@ stabilize 1
----
> 1 receiving messages
3->1 MsgAppResp Term:1 Log:0/11
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 3 [StateSnapshot match=11 next=12 paused pendingSnap=11]
DEBUG 1 recovered from needing snapshot, resumed sending replication messages to 3 [StateSnapshot match=11 commit=0 next=12 paused pendingSnap=11]
> 1 handling Ready
Ready MustSync=false:
Messages:
1->3 MsgApp Term:1 Log:1/11 Commit:11

status 1
----
1: StateReplicate match=11 next=12
2: StateReplicate match=11 next=12
3: StateReplicate match=11 next=12
1: StateReplicate match=11 commit=10 next=12
2: StateReplicate match=11 commit=11 next=12
3: StateReplicate match=11 commit=0 next=12

# Let things settle.
stabilize
Expand Down
2 changes: 1 addition & 1 deletion tracker/progress.go
Original file line number Diff line number Diff line change
Expand Up @@ -250,7 +250,7 @@ func (pr *Progress) IsPaused() bool {

func (pr *Progress) String() string {
var buf strings.Builder
fmt.Fprintf(&buf, "%s match=%d next=%d", pr.State, pr.Match, pr.Next)
fmt.Fprintf(&buf, "%s match=%d commit=%d next=%d", pr.State, pr.Match, pr.Commit, pr.Next)
if pr.IsLearner {
fmt.Fprint(&buf, " learner")
}
Expand Down
7 changes: 4 additions & 3 deletions tracker/progress_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -24,16 +24,17 @@ func TestProgressString(t *testing.T) {
ins := NewInflights(1, 0)
ins.Add(123, 1)
pr := &Progress{
Match: 1,
Next: 2,
Match: 2,
Commit: 1,
Next: 3,
State: StateSnapshot,
PendingSnapshot: 123,
RecentActive: false,
MsgAppFlowPaused: true,
IsLearner: true,
Inflights: ins,
}
const exp = `StateSnapshot match=1 next=2 learner paused pendingSnap=123 inactive inflight=1[full]`
const exp = `StateSnapshot match=2 commit=1 next=3 learner paused pendingSnap=123 inactive inflight=1[full]`
assert.Equal(t, exp, pr.String())
}

Expand Down

0 comments on commit c9ea2f0

Please sign in to comment.