Seeing increase in "Installing snapshot at index ***" messages after upgrade

[LarsWithCA]

Hi @sakno

After upgrading to DotNext.Net.Cluster 5.3.0 (+.NET8) I see the message Installing snapshot at index *** in the leader log every 5-10 minutes.
Before this upgrade (DotNext.Net.Cluster 4.14.1 + .NET8/.NET6) I would almost never see this message.

My setup:

• Linux ARM
• Cluster with 6 nodes
• 10Hz communication frequency

Here's an excerpt of the log of one of the nodes in the cluster that receives a snapshot:

...
2024-04-16 09:36:35.9391|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:35.9391|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:35.9391|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:35.9391|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Incoming configuration with 5857771273067105839 fingerprint from leader. Local fingerprint is 5857771273067105839, apply True
2024-04-16 09:36:36.0417|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.0417|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.0417|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:36.0417|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Incoming configuration with 5857771273067105839 fingerprint from leader. Local fingerprint is 5857771273067105839, apply True
2024-04-16 09:36:36.1629|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.1629|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.1629|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:36.2381|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.2381|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.2381|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:36.2470|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Incoming configuration with 5857771273067105839 fingerprint from leader. Local fingerprint is 5857771273067105839, apply True
2024-04-16 09:36:36.3462|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.3462|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.3462|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:36.3462|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Incoming configuration with 5857771273067105839 fingerprint from leader. Local fingerprint is 5857771273067105839, apply True
2024-04-16 09:36:36.4395|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.4395|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.4395|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
...

What I notice here is there is no Incoming configuration with ... around 09:36:36.1629

Here's an excerpt of the log of the leader during the same time (grouped into three "rounds"):

...
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.1:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.202:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.1:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.202:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.31:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.232:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.31:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.232:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.149:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.31:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.1:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.232:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.149:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.202:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0475|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.149:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0475|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|All changes up to 15149 index are committed. The number of committed entries is 1

2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.1:4250 started at log index 15150
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.31:4250 started at log index 15150
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.1:4250 contains 1 entries. Preceding entry has index 15149 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.31:4250 contains 1 entries. Preceding entry has index 15149 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.202:4250 started at log index 15150
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.202:4250 contains 1 entries. Preceding entry has index 15149 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.149:4250 started at log index 15150
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.149:4250 contains 1 entries. Preceding entry has index 15149 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.1:4250 is replicated successfully starting from index 15150
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.31:4250 is replicated successfully starting from index 15150
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.149:4250 is replicated successfully starting from index 15150
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.232:4250 started at log index 15150
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.202:4250 is replicated successfully starting from index 15150
2024-04-16 09:36:36.1595|INFO|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Installing snapshot at index 15150
2024-04-16 09:36:36.1660|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|All changes up to 15150 index are committed. The number of committed entries is 1
2024-04-16 09:36:36.1660|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.232:4250 is replicated successfully starting from index 15150

2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.202:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.149:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.202:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.149:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.1:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.232:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.31:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.232:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.1:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.1:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.202:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.31:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.149:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.232:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2565|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.31:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2565|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|All changes up to 15151 index are committed. The number of committed entries is 1
...

What I noticed here is Installing snapshot at index 15150 at 09:36:36.1595 + no message saying Replication of 192.168.100.232:4250 contains 1 entries in that "round".

Is this something I should be worried about?
What could be the cause of this particular node receiving a snapshot once in a while - as the (almost) only one?
Please let me know if there is something I can do to investigate further.

Cheers,
Lars

[LarsWithCA]

I just tried DotNext.Net.Cluster 4.14.1 + .NET8 and I almost never see this message.

[sakno]

What the IP address of the node which receives the snapshot? What kind of log compaction are you using?

[LarsWithCA]

Wouldn't WAL look like 'S' only when a compaction has just happened - which only happens when you exceed 'recordsPerPartition'?
Do all of the compaction modes have a time window where the WAL contains only a snapshot forcing some followers to install the snapshot (instead of getting the log entries they're missing)?

[sakno]

happens when you exceed recordsPerPartition

This is correct. I was wrong. However, I still think that the behavior is observable because of aggressive compaction. What's the value of recordsPerPartition? And how frequently you perform writes (and subsequent calls of ForceReplicationAsync)?

[LarsWithCA]

recordsPerPartition=50. We write 10 times per second.

[sakno]

Installing snapshot at index 15150

This line is taken from the log above. 15150 mod 50 = 0, so the replication of log entry 15150 can be snapshot installation or regular log entry depending on the nature of the last changes.

[sakno]

However, I think that the change needs to be reverted. The transfer of snapshot must be avoided if cluster operates normally because the size of snapshot can be large enough to introduce unnecessary latency.

[LarsWithCA]

Messages gone in dev build. Closing.

[LarsWithCA]

Fixed in 5.5.0