constant leadership changes

[nivekuil]

After failing to upgrade to 22.2.x (#6640), I notice that there's a lot of leadership change activity. What's going on, and how can this be fixed?

[emaxerrno]

Need redpanda logs. Are you getting timeouts ?

[nivekuil]

Seems so, according to logs from controller leader:

Oct 09 02:28:50 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:50,811 [shard 0] cluster - leader_balancer.cc:385 - Leadership movement for group 489 from {node_id: 2, shard: 0} to {node_id: 1, shard: 0} timed out (leader_shard {{node_id: 2, shard: 0}})
Oct 09 02:28:50 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:50,811 [shard 0] raft - [group_id:510, {kafka/user-consumed-item/0}] consensus.cc:2757 - Starting leadership transfer from {id: {2}, revision: {8460}} to {id: {1}, revision: {8460}} in term 857
Oct 09 02:28:50 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:50,812 [shard 0] raft - [group_id:510, {kafka/user-consumed-item/0}] consensus.cc:152 - [leadership_transfer] Stepping down as leader in term 857, dirty offset 1879
Oct 09 02:28:52 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:52,786 [shard 0] raft - [group_id:510, {kafka/user-consumed-item/0}] vote_stm.cc:76 - vote reply from {id: {1}, revision: {8460}} - {term:{858}, target_node_id{id: {2}, revision: {8460}}, vote_granted: 1, log_ok:1}
Oct 09 02:28:52 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:52,787 [shard 0] raft - [group_id:510, {kafka/user-consumed-item/0}] vote_stm.cc:255 - becoming the leader term:858
Oct 09 02:28:52 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:52,787 [shard 0] raft - [group_id:510, {kafka/user-consumed-item/0}] vote_stm.cc:76 - vote reply from {id: {0}, revision: {8460}} - {term:{858}, target_node_id{id: {2}, revision: {8460}}, vote_granted: 1, log_ok:1}
Oct 09 02:28:52 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:52,790 [shard 0] storage - segment.cc:626 - Creating new segment /var/lib/redpanda/data/kafka/user-consumed-item/0_8460/1880-858-v1.log
Oct 09 02:28:52 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:52,791 [shard 0] cluster - ntp: {kafka/user-consumed-item/0} - archival_metadata_stm.cc:407 - creating snapshot at offset: 1879, remote start_offset: -9223372036854775808, last_offset: -9223372036854775808
Oct 09 02:28:52 dro-3 example.pod.redpanda_redpanda[275177]: INFO  2022-10-09 02:28:52,847 [shard 0] raft - [group_id:510, {kafka/user-consumed-item/0}] vote_stm.cc:270 - became the leader term:858

Logs from another broker:

Oct 09 02:24:19 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:19,567 [shard 0] raft - [group_id:530, {kafka/events-KSTREAM-REDUCE-STATE-STORE-0000000017-changelog/0}] consensus.cc:2757 - Starting leadership transfer from {id: {0}, revision: {8472}} to {id: {1}, 
revision: {8472}} in term 776
Oct 09 02:24:19 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:19,568 [shard 0] raft - [group_id:530, {kafka/events-KSTREAM-REDUCE-STATE-STORE-0000000017-changelog/0}] consensus.cc:152 - [leadership_transfer] Stepping down as leader in term 776, dirty offset 1668
Oct 09 02:24:21 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:21,811 [shard 0] raft - [group_id:530, {kafka/events-KSTREAM-REDUCE-STATE-STORE-0000000017-changelog/0}] vote_stm.cc:76 - vote reply from {id: {2}, revision: {8472}} - {term:{777}, target_node_id{id: 
{0}, revision: {8472}}, vote_granted: 1, log_ok:1}
Oct 09 02:24:21 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:21,811 [shard 0] raft - [group_id:530, {kafka/events-KSTREAM-REDUCE-STATE-STORE-0000000017-changelog/0}] vote_stm.cc:255 - becoming the leader term:777
Oct 09 02:24:21 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:21,811 [shard 0] raft - [group_id:530, {kafka/events-KSTREAM-REDUCE-STATE-STORE-0000000017-changelog/0}] vote_stm.cc:76 - vote reply from {id: {1}, revision: {8472}} - {term:{777}, target_node_id{id: 
{0}, revision: {8472}}, vote_granted: 1, log_ok:1}
Oct 09 02:24:21 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:21,814 [shard 0] storage - segment.cc:626 - Creating new segment /var/lib/redpanda/data/kafka/events-KSTREAM-REDUCE-STATE-STORE-0000000017-changelog/0_8472/1669-777-v1.log
Oct 09 02:24:21 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:21,870 [shard 0] raft - [group_id:530, {kafka/events-KSTREAM-REDUCE-STATE-STORE-0000000017-changelog/0}] vote_stm.cc:270 - became the leader term:777
Oct 09 02:24:38 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:38,469 [shard 0] raft - [group_id:2580, {kafka/events-KSTREAM-AGGREGATE-STATE-STORE-0000000004-changelog/0}] consensus.cc:2757 - Starting leadership transfer from {id: {0}, revision: {11759}} to {id: 
{1}, revision: {11759}} in term 25
Oct 09 02:24:38 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:38,470 [shard 0] raft - [group_id:2580, {kafka/events-KSTREAM-AGGREGATE-STATE-STORE-0000000004-changelog/0}] consensus.cc:152 - [leadership_transfer] Stepping down as leader in term 25, dirty offset 9
8
Oct 09 02:24:40 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:40,002 [shard 0] raft - [group_id:2580, {kafka/events-KSTREAM-AGGREGATE-STATE-STORE-0000000004-changelog/0}] vote_stm.cc:76 - vote reply from {id: {2}, revision: {11759}} - {term:{26}, target_node_id{
id: {0}, revision: {11759}}, vote_granted: 1, log_ok:1}
Oct 09 02:24:40 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:40,002 [shard 0] raft - [group_id:2580, {kafka/events-KSTREAM-AGGREGATE-STATE-STORE-0000000004-changelog/0}] vote_stm.cc:76 - vote reply from {id: {1}, revision: {11759}} - {term:{26}, target_node_id{
id: {0}, revision: {11759}}, vote_granted: 1, log_ok:1}
Oct 09 02:24:40 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:40,002 [shard 0] raft - [group_id:2580, {kafka/events-KSTREAM-AGGREGATE-STATE-STORE-0000000004-changelog/0}] vote_stm.cc:255 - becoming the leader term:26
Oct 09 02:24:40 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:40,007 [shard 0] storage - segment.cc:626 - Creating new segment /var/lib/redpanda/data/kafka/events-KSTREAM-AGGREGATE-STATE-STORE-0000000004-changelog/0_11759/99-26-v1.log
Oct 09 02:24:40 dro-1 example.pod.redpanda_redpanda[294856]: INFO  2022-10-09 02:24:40,057 [shard 0] raft - [group_id:2580, {kafka/events-KSTREAM-AGGREGATE-STATE-STORE-0000000004-changelog/0}] vote_stm.cc:270 - became the leader term:26

[emaxerrno]

you have the leadership transfer feature on leadership_transfer - see the docs - but basically we offer on the free version leadership balancing to ensure cross sectional bandwidth utilization. you can turn it off if you'd like, but this is an anti-entropy mechanism to ensure nodes are equally balanced over time.

[nivekuil]

I think this is enable_leader_balancer which defaults to true? It sounds good, just not sure why it started happening all of a sudden. Symptomatic of something else?

[emaxerrno]

could be the new version? but looks like you downgraded? something is causing an imbalance in your cluster, hard to tell from the logs your shared, but the controller is seeing imablance and is trying to fix it.