时不时日志同步时出现reject term_unmatched

[hanzhihua]

Your question

时不时日志同步时出现reject term_unmatched ，主要会有什么场景造成呢？
问一下handleAppendEntriesRequest处理是单线程吗？leader pipeline发送不会乱序 把
请指教

Your scenes

Describe your use scenes (why need this feature)

Your advice

Describe the advice or solution you'd like

Environment

• SOFAJRaft version: 1.2.6
• JVM version (e.g. java -version): 1.8
• OS version (e.g. uname -a):4.9
• Maven version:
• IDE version:

[fengjiachun]

问一下handleAppendEntriesRequest处理是单线程吗？leader pipeline发送不会乱序 把

不会乱序

term_unmatched 是 term 不匹配，原因一般要具体 case 具体看，举例比如日志里的 localPrevLogTerm == 0， 那么一般就是上一条日志当前 follower 节点都还没有， leader 需要回退 index 并再次发送；如果 localPrevLogTerm != 0，通常代表数据存在不一致，不过更有可能是一个无效的 leader 发来的日志；以上，通常不会导致什么问题，一般是正常的。
最后，如果你在进程活着的期间删除过数据，导致了内存状态与磁盘数据不一致，那么前边的不用考虑，禁止掉这种行为就行。

[killme2008]

可能是发生重新选举了吧，我猜测是跟过载有关系 ，跟这个类似 #845

可以看看有没有重新选举的日志

[ReycoLi]

我们也遇到了同样的问题，目前我们还没有enable snapshot(正在做)，所以新加入的点要从0开始replicate。目前数据量不大， 只有一百万条log, 每次加新点都会时不时出现reject term_unmatched这个error，确认过过程中没有重新选举，也没有删除数据。

过后看了一些这个错误， 都是localPrevLogTerm=0，我的理解就像你们说的 “上一条日志当前 follower 节点都还没有”。也就是follower还没有接收或者handle上一条request，就开始handle下一条AppendEntriesRequest了。 不理解这个情况是怎么发生的，如果我的理解不对，劳烦指正，谢谢。

[fengjiachun]

我们也遇到了同样的问题，目前我们还没有enable snapshot(正在做)，所以新加入的点要从0开始replicate。目前数据量不大， 只有一百万条log, 每次加新点都会时不时出现reject term_unmatched这个error，确认过过程中没有重新选举，也没有删除数据。

过后看了一些这个错误， 都是localPrevLogTerm=0，我的理解就像你们说的 “上一条日志当前 follower 节点都还没有”。也就是follower还没有接收或者handle上一条request，就开始handle下一条AppendEntriesRequest了。 不理解这个情况是怎么发生的，如果我的理解不对，劳烦指正，谢谢。

不难理解啊，新上的节点，leader 也不知道从哪一条日志开始给它同步，先尝试了 index = n，结果这个 follower 连 n-1 的 log 也没有，那么 follower 就只能拒绝这次 log 同步（就出现了上面的日志），然后返回给 leader。leader 则需要尝试发送 index 更小的 log，如果 leader 已经因为 snapshot 裁剪了自己的日志，那么就需要把自己的 snapshot 发送给这个 follower

[ReycoLi]

我们也遇到了同样的问题，目前我们还没有enable snapshot(正在做)，所以新加入的点要从0开始replicate。目前数据量不大， 只有一百万条log, 每次加新点都会时不时出现reject term_unmatched这个error，确认过过程中没有重新选举，也没有删除数据。
过后看了一些这个错误， 都是localPrevLogTerm=0，我的理解就像你们说的 “上一条日志当前 follower 节点都还没有”。也就是follower还没有接收或者handle上一条request，就开始handle下一条AppendEntriesRequest了。 不理解这个情况是怎么发生的，如果我的理解不对，劳烦指正，谢谢。

不难理解啊，新上的节点，leader 也不知道从哪一条日志开始给它同步，先尝试了 index = n，结果这个 follower 连 n-1 的 log 也没有，那么 follower 就只能拒绝这次 log 同步（就出现了上面的日志），然后返回给 leader。leader 则需要尝试发送 index 更小的 log，如果 leader 已经因为 snapshot 裁剪了自己的日志，那么就需要把自己的 snapshot 发送给这个 follower

举个例子，现在leader有10000条log, 新加的follower只有5000条，像你所说，leader会一直尝试发送 index 更小的 log，直到找到follower需要从5000条开始复制，这个过程中有reject term_unmatched这个error我可以理解，但是leader一旦找到起始点(也就是5000)，然后帮follower复制5001-10000的这个过程中, follower如果是顺序处理这5000-10000的requests话，为什么follower还是会出现reject term_unmatched这个error?
我们目前没有enable snapshot, leader有全部的日志，我们遇到的就像上面描述的，follower已经开始正常的复制了，开始复制到最后结束还是偶尔会有reject term_unmatched这个error。

[fengjiachun]

可以把你描述的这种情况的日志贴上来，看看是怎么回事

[ReycoLi]

好像快复制完的时候发生的更频繁一些，reject term_unmatched错误的周围，几乎没有sofaJRaft相关的Info level及以上的log，只有几条onConfigurationCommitted的info log（如截图），我在想会不会在 apply configuration log的时候会对这条configuration log前后的data log的处理造成影响？感觉理论上应该不会

[hanzhihua]

日志同步不是先做probe,拿到了follower的正确的nextIndex,后续的Replicator.sendEntity是顺序发送的，那么到iobuffer、socket buffer中应该是也是有序的，到了follower端，通过decode,process会不会有多线程乱序的情况呢？如果做过处理就不应该是乱序的，而且handleAppendEntriesRequest里面已经调用了logManager.appendEntries，不应该出现term_unmatched，好奇怪
，请指教

[fengjiachun]

日志同步不是先做probe,拿到了follower的正确的nextIndex,后续的Replicator.sendEntity是顺序发送的，那么到iobuffer、socket buffer中应该是也是有序的，到了follower端，通过decode,process会不会有多线程乱序的情况呢？如果做过处理就不应该是乱序的，而且handleAppendEntriesRequest里面已经调用了logManager.appendEntries，不应该出现term_unmatched，好奇怪

，请指教

log 不是发一批然后等待 response 再发下一批的，你可以在代码里看到一个 inflights queue，它实现了类似 pipeline 的发送，是异步发出去的，pipeline 用于维护和确保数据包的顺序性。所以 log 是连续发送出去的。也就是说 unmatched 的日志，很可能会在短期连续出现一批（因为这个 pipeline 的机制）除此之外。如果 leader 收到并处理 response 等了很长时间（需要根据 response 重置 nextindex），那么这个现象会更严重一些。

最后，可以把 leader 和对应 follower 的日志一块拿出来分析下

[hanzhihua]

你的意思，如果leader处理慢也会造成这种情况
目前线上unmatched是偶尔出现，而且不影响使用，我主要是在机制上不太理解，多谢

[fengjiachun]

你的意思，如果leader处理慢也会造成这种情况

目前线上unmatched是偶尔出现，而且不影响使用，我主要是在机制上不太理解，多谢

嗯，我上面的解释是想说明为什么这个 unmatched 日志会一下子出现这么多次。

[hanzhihua]

我注意到同步日志，leader端发送是有序，follower也是单线程同步处理(logmanager写入)，就是回复是异步，但也做了同步处理，leader接受response也做了同步处理。
但出现日志错误 follower unmatch 全部是localPrevLogTerm=0, lastLogIndex< request中的prevLogIndex，这个应该表明leader的replicator nextindex是不正确的，但同步前不是做过了probe。
这个错误时不时会出现，而且全称没有leader切换，这个跟leader处理慢怎么解释呢，感觉不应该呀
@fengjiachun 能帮忙分析一下吗，多谢

[killme2008]

pipeline 导致的，上一批没处理完，下一批就来了，不影响正确性。也可以解释成为什么是在新节点加入的时候出现比较频繁，这时候大量日志要复制，pipeline 塞满了请求，follower 处理的慢，leader 还在继续发。

可以在 follower 节点搜索下有没有 busy 或者 overload 这样的日志。

pipeline 的目的就是加快复制，将带宽尽量用满。

这个问题更好的解决办法是引入协商的流量控制机制。

[hanzhihua]

我看到handleAppendEntriesRequest这个方法是单线程的，而且是同步的，有lock，而且是同步写到logmanager中。如果发送是顺序的，出现term_unmatched就有点奇怪。
如果follower处理慢，最多只是leader rpc请求超时，就应该是重新做做prob，然后在同步，也不应该出现term_unmatched
不知道在哪里没有理解对

[fengjiachun]

如果发送是顺序的

”发送“是顺序的，但并不能在异步的网络中保证什么，底层的连接 （channel） jraft 会尽量的保证使用相同的一个，但连接也可能断掉并新建的，还有 prob 也是 appendEntry，也是会触发 term_unmatched 日志，prob 也可能跟有效数据一块在 pipeline 发送，因为 pipleline 的机制，也会出现一批的 unmatched 日志

[hanzhihua]

如果 term_unmatched 错误日志 是prob日志，entriesSize=0，我是可以理解的，但很多都是entriesSize都是大于0，就有点费解。
就算出现了重连情况，发过去到follower端的应该都是有序的，没有发过去的这批会全部清掉，然后做一次prob，这次可能会term_unmatched，但后面的发送，不应该出现term_unmatched，请大佬分析一下，多谢

[fengjiachun]

如果 term_unmatched 错误日志 是prob日志，entriesSize=0，我是可以理解的，但很多都是entriesSize都是大于0，就有点费解

pipeline 是一大批的，上面不是说了么

就算出现了重连情况，发过去到follower端的应该都是有序的，没有发过去的这批会全部清掉，然后做一次prob，这次可能会term_unmatched，但后面的发送，不应该出现term_unmatched，请大佬分析一下，多谢

你一直是串行，一 request 一 response 的思路在思考，你看下我和 @killme2008 说的 pipeline 机制的代码，该说明的应该都包含在上面回复了

[fengjiachun]

如果你要分析具体问题，可以参考我的建议把日志发出来分析下问题发生的过程，如果是对代码逻辑有疑问，还是再仔细看下代码吧

[fengjiachun]

我先关闭了，如果有具体日志，想分析过程的话可以再打开

[hanzhihua]

我明白为什么这么多term_unmatched，主要是leader发送时出现了 write overflow!，然后用异步的方法处理了这个异常。

有点奇怪，这样写iobuffer本身就是同步操作，而且发送在leader端，为什么不马上停止后续的发送，造成没有必要的网络开销

[fengjiachun]

主要是leader发送时出现了 write overflow!

理论上这也会导致中间数据丢了 然后 unmatched，建议下次一次性把信息说全

为什么不马上停止后续的发送，造成没有必要的网络开销

这不是没必要的，如果不理解，可参考 gRPC streaming

[fengjiachun]

忘了说, write overflow 的话可以调一下 bolt/netty 的参数，可以调大一些