search

sofastack / sofa-jraft

A production-grade java implementation of RAFT consensus algorithm.
https://www.sofastack.tech/projects/sofa-jraft/
Apache License 2.0
3.57k stars 1.14k forks source link

Leader Inconsistency #954

Closed nkorange closed 1 year ago

nkorange commented 1 year ago

Describe the bug

I deployed 3 Nacos 2.1.2 servers, which uses JRaft 1.3.8. At first everything is good.

Then I restarted nacos0 and nacos1, and now there are two leaders: nacos1 and nacos2.

Expected behavior

There is only one leader.

Actual behavior

There are two leaders.

logs on nacos0:

2023-04-04 16:04:46,088 INFO shutdown jraft server

2023-04-04 16:04:46,091 INFO ========= The raft protocol is starting to close =========

2023-04-04 16:04:46,397 INFO ========= The raft protocol has been closed =========

2023-04-04 16:05:21,875 INFO Initializes the Raft protocol, raft-config info : {}

2023-04-04 16:05:22,770 INFO ========= The raft protocol is starting... =========

2023-04-04 16:05:23,688 INFO ========= The raft protocol start finished... =========

2023-04-04 16:05:23,769 INFO create raft group : naming_persistent_service

2023-04-04 16:05:25,861 INFO This Raft event changes : RaftEvent{groupId='naming_persistent_service', leader='nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848', term=2, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:05:31,573 ERROR ReadIndex has error : read-index request timeout, go to Leader read.

2023-04-04 16:05:36,169 INFO create raft group : naming_persistent_service_v2

2023-04-04 16:05:36,466 INFO create raft group : naming_instance_metadata

2023-04-04 16:05:36,480 INFO This Raft event changes : RaftEvent{groupId='naming_persistent_service_v2', leader='nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848', term=2, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:05:36,664 INFO create raft group : naming_service_metadata

2023-04-04 16:05:36,872 INFO This Raft event changes : RaftEvent{groupId='naming_service_metadata', leader='nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848', term=2, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:05:37,064 INFO This Raft event changes : RaftEvent{groupId='naming_instance_metadata', leader='nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848', term=2, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:06:01,002 INFO This Raft event changes : RaftEvent{groupId='naming_service_metadata', leader='nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848', term=3, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:06:01,093 INFO This Raft event changes : RaftEvent{groupId='naming_persistent_service', leader='nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848', term=3, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:06:01,262 INFO This Raft event changes : RaftEvent{groupId='naming_persistent_service_v2', leader='nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848', term=3, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:06:01,264 INFO This Raft event changes : RaftEvent{groupId='naming_instance_metadata', leader='nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848', term=3, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

logs on nacos1:

2023-04-04 16:06:00,891 INFO shutdown jraft server

2023-04-04 16:06:00,894 INFO ========= The raft protocol is starting to close =========

2023-04-04 16:06:01,194 INFO ========= The raft protocol has been closed =========

2023-04-04 16:06:44,499 INFO Initializes the Raft protocol, raft-config info : {}

2023-04-04 16:06:45,506 INFO ========= The raft protocol is starting... =========

2023-04-04 16:06:46,799 INFO ========= The raft protocol start finished... =========

2023-04-04 16:06:46,812 INFO create raft group : naming_persistent_service

2023-04-04 16:06:52,199 ERROR ReadIndex has error : No leader at term 0., go to Leader read.

2023-04-04 16:06:53,697 INFO This Raft event changes : RaftEvent{groupId='naming_persistent_service', leader='nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848', term=3, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:06:54,108 ERROR ReadIndex has error : read-index request timeout, go to Leader read.

2023-04-04 16:06:56,699 INFO create raft group : naming_persistent_service_v2

2023-04-04 16:06:56,992 INFO create raft group : naming_instance_metadata

2023-04-04 16:06:57,288 INFO This Raft event changes : RaftEvent{groupId='naming_persistent_service_v2', leader='nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848', term=3, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:06:57,288 INFO create raft group : naming_service_metadata

2023-04-04 16:06:57,295 INFO This Raft event changes : RaftEvent{groupId='naming_instance_metadata', leader='nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848', term=3, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:06:57,888 INFO This Raft event changes : RaftEvent{groupId='naming_service_metadata', leader='nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848', term=3, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

logs on nacos2:

2023-04-04 16:04:46,288 INFO This Raft event changes : RaftEvent{groupId='naming_service_metadata', leader='nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848', term=2, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:04:46,300 INFO This Raft event changes : RaftEvent{groupId='naming_persistent_service', leader='nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848', term=2, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:04:46,495 INFO This Raft event changes : RaftEvent{groupId='naming_instance_metadata', leader='nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848', term=2, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

2023-04-04 16:04:46,495 INFO This Raft event changes : RaftEvent{groupId='naming_persistent_service_v2', leader='nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848', term=2, raftClusterInfo=[nacos-test-1.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-2.nacos-test-headless.nacos.svc.base.local:7848, nacos-test-0.nacos-test-headless.nacos.svc.base.local:7848]}

Steps to reproduce

  1. deploy 3 nacos 2.1.2 nodes.
  2. restart nacos0 and nacos1.

Minimal yet complete reproducer code (or GitHub URL to code)

Environment

killme2008 commented 1 year ago

Please report it to nacos project.

If you think the issue is in jraft, please provide a simple election example to reproduce the issue.

killme2008 commented 1 year ago

Note: looks like there are three raft groups in the log:

Every group has different leaders, it's expected.

nkorange commented 1 year ago

@killme2008 Hi, the problem is for a particular group, there are different leaders.

For example, the group naming_persistent_service_v2 has two leaders.

killme2008 commented 1 year ago

@killme2008 Hi, the problem is for a particular group, there are different leaders.

For example, the group naming_persistent_service_v2 has two leaders.

It's ok because the term is different. When the lower-term leader tries to replicate logs to other followers, the followers will reject.

nkorange commented 1 year ago

@killme2008 Hi, the problem is for a particular group, there are different leaders. For example, the group naming_persistent_service_v2 has two leaders.

It's ok because the term is different. When the lower-term leader tries to replicate logs to other followers, the followers will reject.

These are the last parts of the logs. Should they come to the same term eventually?

killme2008 commented 1 year ago

@killme2008 Hi, the problem is for a particular group, there are different leaders. For example, the group naming_persistent_service_v2 has two leaders.

It's ok because the term is different. When the lower-term leader tries to replicate logs to other followers, the followers will reject.

These are the last parts of the logs. Should they come to the same term eventually?

Of course. If the lower-term leader found there is a high-term leader already existing, it will step down. And the new leader will try to replicate logs to it and cast it to a follower.

FYI: These logs are printed by nacos, not jraft. The jraft log may be in a different log file. You can find more detail logs in it.

nkorange commented 1 year ago

@killme2008 Hi I found some JRaft logs on nacos1 at 16:06:57,288 when nacos1 changed its leader to nacos2:

image

Did it mean something?

nkorange commented 1 year ago

The cause is the data directory is removed at the restart of Nacos.