Skip to content

Add test for keeper 2 node configuration#28526

Merged
alesapin merged 4 commits intomasterfrom
add_test_for_two_nodes_configuration
Sep 6, 2021
Merged

Add test for keeper 2 node configuration#28526
alesapin merged 4 commits intomasterfrom
add_test_for_two_nodes_configuration

Conversation

@alesapin
Copy link
Copy Markdown
Member

@alesapin alesapin commented Sep 2, 2021

I hereby agree to the terms of the CLA available at: https://yandex.ru/legal/cla/?lang=en

Changelog category (leave one):

  • Not for changelog (changelog entry is not required)

Non-HA 2-nodes configuration works OK with current implementation. There is a possibility in NuRaft to enable auto adjustment for quorum size in case of two nodes, so if one node down other will became leader. But in case of network partition it will lead to split brain (both will became leaders), so I don't want to add an ability to turn it on.

@robot-clickhouse robot-clickhouse added the pr-not-for-changelog This PR should not be mentioned in the changelog label Sep 2, 2021
@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Sep 3, 2021

Didn't raise the exception and I don't understand why. Need to investigate

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Sep 3, 2021

Client:

2021-09-02 22:15:37 [ 321 ] DEBUG : Sending request(xid=1): Create(path='/test_read_write_blocked_node1', data=b'somedata1', acl=[ACL(perms=31, acl_list=['ALL'], id=Id(scheme='world', id='anyone'))], flags=0) (connection.py:312, _submit)
2021-09-02 22:15:44 [ 321 ] DEBUG : Received response(xid=1): '/test_read_write_blocked_node1' (connection.py:410, _read_response)

Node1:

2021.09.02 22:15:37.624757 [ 19 ] {} <Debug> RaftInstance: Receive a client_request message from 0 with LastLogIndex=0, LastLogTerm=0, EntriesLength=1, CommitIndex=0 and Term=0
2021.09.02 22:15:37.624905 [ 19 ] {} <Debug> RaftInstance: append at log_idx 28
2021.09.02 22:15:37.625227 [ 55 ] {} <Trace> RaftInstance: send request to 2
2021.09.02 22:15:37.625361 [ 55 ] {} <Trace> RaftInstance: last_log_idx: 27, starting_idx: 1, cur_nxt_idx: 29
2021.09.02 22:15:37.625481 [ 55 ] {} <Debug> RaftInstance: append_entries for 2 with LastLogIndex=27, LastLogTerm=1, EntriesLength=1, CommitIndex=27, Term=1, peer_last_sent_idx 28
2021.09.02 22:15:37.625541 [ 55 ] {} <Debug> RaftInstance: idx: 28
2021.09.02 22:15:37.625624 [ 55 ] {} <Trace> RaftInstance: send req 1 -> 2, type append_entries_request
2021.09.02 22:15:37.625829 [ 55 ] {} <Trace> RaftInstance: sent
2021.09.02 22:15:37.792313 [ 40 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:37.792447 [ 40 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:37.792537 [ 40 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:38.000317 [ 202 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.16 GiB, peak 2.16 GiB, will set to 2.16 GiB (RSS), difference: 2.53 MiB
2021.09.02 22:15:38.292746 [ 47 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:38.292855 [ 47 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:38.292939 [ 47 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:38.293022 [ 47 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 667 ms ago
2021.09.02 22:15:38.793274 [ 45 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:38.793387 [ 45 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:38.793476 [ 45 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:38.793561 [ 45 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 1167 ms ago
2021.09.02 22:15:39.000308 [ 202 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.16 GiB, peak 2.16 GiB, will set to 2.16 GiB (RSS), difference: 3.05 MiB
2021.09.02 22:15:39.293859 [ 23 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:39.293999 [ 23 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:39.294101 [ 23 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:39.294189 [ 23 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 1668 ms ago
2021.09.02 22:15:39.794478 [ 50 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:39.794614 [ 50 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:39.794709 [ 50 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:39.794790 [ 50 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 2168 ms ago
2021.09.02 22:15:39.820087 [ 65 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushing system log, 6864 entries to flush up to offset 6864
2021.09.02 22:15:39.820350 [ 65 ] {} <Debug> SystemLog (system.asynchronous_metric_log): Creating new table system.asynchronous_metric_log for AsynchronousMetricLog
2021.09.02 22:15:39.834074 [ 65 ] {} <Debug> system.asynchronous_metric_log (89ca21e4-fbbe-45ce-89ca-21e4fbbe15ce): Loading data parts
2021.09.02 22:15:39.834306 [ 65 ] {} <Debug> system.asynchronous_metric_log (89ca21e4-fbbe-45ce-89ca-21e4fbbe15ce): There are no data parts
2021.09.02 22:15:39.867125 [ 65 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 19.96 GiB.
2021.09.02 22:15:39.887575 [ 65 ] {} <Trace> system.asynchronous_metric_log (89ca21e4-fbbe-45ce-89ca-21e4fbbe15ce): Renaming temporary part tmp_insert_202109_1_1_0 to 202109_1_1_0.
2021.09.02 22:15:39.888464 [ 65 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushed system log up to offset 6864
2021.09.02 22:15:40.000324 [ 202 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.16 GiB, peak 2.17 GiB, will set to 2.18 GiB (RSS), difference: 18.58 MiB
2021.09.02 22:15:40.295060 [ 24 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:40.295173 [ 24 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:40.295262 [ 24 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:40.295369 [ 24 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 2669 ms ago
2021.09.02 22:15:40.314420 [ 59 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 4 entries to flush up to offset 4
2021.09.02 22:15:40.314669 [ 59 ] {} <Debug> SystemLog (system.query_log): Creating new table system.query_log for QueryLog
2021.09.02 22:15:40.315387 [ 60 ] {} <Trace> SystemLog (system.query_thread_log): Flushing system log, 4 entries to flush up to offset 4
2021.09.02 22:15:40.315638 [ 60 ] {} <Debug> SystemLog (system.query_thread_log): Creating new table system.query_thread_log for QueryThreadLog
2021.09.02 22:15:40.319157 [ 64 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush up to offset 8
2021.09.02 22:15:40.319429 [ 64 ] {} <Debug> SystemLog (system.metric_log): Creating new table system.metric_log for MetricLog
2021.09.02 22:15:40.347785 [ 60 ] {} <Debug> system.query_thread_log (42862363-efcf-48e2-8286-2363efcf18e2): Loading data parts
2021.09.02 22:15:40.348184 [ 60 ] {} <Debug> system.query_thread_log (42862363-efcf-48e2-8286-2363efcf18e2): There are no data parts
2021.09.02 22:15:40.362600 [ 59 ] {} <Debug> system.query_log (d60e90b8-f0c5-4808-960e-90b8f0c55808): Loading data parts
2021.09.02 22:15:40.362964 [ 59 ] {} <Debug> system.query_log (d60e90b8-f0c5-4808-960e-90b8f0c55808): There are no data parts
2021.09.02 22:15:40.366876 [ 60 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 19.96 GiB.
2021.09.02 22:15:40.380049 [ 60 ] {} <Trace> system.query_thread_log (42862363-efcf-48e2-8286-2363efcf18e2): Renaming temporary part tmp_insert_202109_1_1_0 to 202109_1_1_0.
2021.09.02 22:15:40.382618 [ 60 ] {} <Trace> SystemLog (system.query_thread_log): Flushed system log up to offset 4
2021.09.02 22:15:40.390475 [ 59 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 19.96 GiB.
2021.09.02 22:15:40.412210 [ 59 ] {} <Trace> system.query_log (d60e90b8-f0c5-4808-960e-90b8f0c55808): Renaming temporary part tmp_insert_202109_1_1_0 to 202109_1_1_0.
2021.09.02 22:15:40.416355 [ 59 ] {} <Trace> SystemLog (system.query_log): Flushed system log up to offset 4
2021.09.02 22:15:40.423301 [ 64 ] {} <Debug> system.metric_log (01ae3a17-7deb-451f-81ae-3a177debe51f): Loading data parts
2021.09.02 22:15:40.423625 [ 64 ] {} <Debug> system.metric_log (01ae3a17-7deb-451f-81ae-3a177debe51f): There are no data parts
2021.09.02 22:15:40.512667 [ 64 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 19.96 GiB.
2021.09.02 22:15:40.572923 [ 64 ] {} <Trace> system.metric_log (01ae3a17-7deb-451f-81ae-3a177debe51f): Renaming temporary part tmp_insert_202109_1_1_0 to 202109_1_1_0.
2021.09.02 22:15:40.587094 [ 64 ] {} <Trace> SystemLog (system.metric_log): Flushed system log up to offset 8
2021.09.02 22:15:40.795678 [ 22 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:40.795835 [ 22 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:40.795932 [ 22 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:40.796031 [ 22 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 3170 ms ago
2021.09.02 22:15:41.000318 [ 202 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.18 GiB, peak 2.19 GiB, will set to 2.25 GiB (RSS), difference: 70.69 MiB
2021.09.02 22:15:41.296295 [ 52 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:41.296405 [ 52 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:41.296488 [ 52 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:41.296573 [ 52 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 3670 ms ago
2021.09.02 22:15:41.796851 [ 29 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:41.796971 [ 29 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:41.797057 [ 29 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:41.797141 [ 29 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 4171 ms ago
2021.09.02 22:15:42.000332 [ 202 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.25 GiB, peak 2.25 GiB, will set to 2.25 GiB (RSS), difference: 3.35 MiB
2021.09.02 22:15:42.297402 [ 26 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:42.297558 [ 26 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:42.297648 [ 26 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:42.297736 [ 26 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 4671 ms ago
2021.09.02 22:15:42.797983 [ 53 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:42.798093 [ 53 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:42.798179 [ 53 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:42.798270 [ 53 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 5172 ms ago
2021.09.02 22:15:43.000359 [ 202 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.25 GiB, peak 2.25 GiB, will set to 2.26 GiB (RSS), difference: 1.82 MiB
2021.09.02 22:15:43.298530 [ 25 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:43.298641 [ 25 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:43.298726 [ 25 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:43.298806 [ 25 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 5672 ms ago
2021.09.02 22:15:43.799085 [ 28 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:43.799207 [ 28 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:43.799297 [ 28 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:43.799382 [ 28 ] {} <Warning> RaftInstance: skipped sending msg to 2 too long time, last msg sent 6173 ms ago
2021.09.02 22:15:44.000320 [ 202 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.26 GiB, peak 2.26 GiB, will set to 2.26 GiB (RSS), difference: 1.81 MiB
2021.09.02 22:15:44.268210 [ 18 ] {} <Trace> NuKeeperTCPHandler: Received heartbeat for session #5
2021.09.02 22:15:44.297416 [ 33 ] {} <Trace> RaftInstance: resp of req 1 -> 2, type append_entries_request, OK
2021.09.02 22:15:44.297566 [ 33 ] {} <Debug> RaftInstance: Receive a append_entries_response message from peer 2 with Result=1, Term=1, NextIndex=29
2021.09.02 22:15:44.297648 [ 33 ] {} <Trace> RaftInstance: src: 2, dst: 1, resp->get_term(): 1
2021.09.02 22:15:44.297744 [ 33 ] {} <Trace> RaftInstance: handle append entries resp (from 2), resp.get_next_idx(): 29
2021.09.02 22:15:44.297819 [ 33 ] {} <Trace> RaftInstance: peer 2 batch size hint: 0 bytes
2021.09.02 22:15:44.297892 [ 33 ] {} <Trace> RaftInstance: peer 2, prev matched idx: 27, new matched idx: 28
2021.09.02 22:15:44.297973 [ 33 ] {} <Trace> RaftInstance: quorum idx 1, 28 28 
2021.09.02 22:15:44.298034 [ 33 ] {} <Debug> RaftInstance: trigger commit upto 28
2021.09.02 22:15:44.298099 [ 33 ] {} <Trace> RaftInstance: send request to 2
2021.09.02 22:15:44.298180 [ 33 ] {} <Trace> RaftInstance: last_log_idx: 28, starting_idx: 1, cur_nxt_idx: 29
2021.09.02 22:15:44.298273 [ 33 ] {} <Debug> RaftInstance: append_entries for 2 with LastLogIndex=28, LastLogTerm=1, EntriesLength=0, CommitIndex=28, Term=1, peer_last_sent_idx 28
2021.09.02 22:15:44.298335 [ 33 ] {} <Trace> RaftInstance: EMPTY PAYLOAD
2021.09.02 22:15:44.298405 [ 33 ] {} <Trace> RaftInstance: send req 1 -> 2, type append_entries_request
2021.09.02 22:15:44.298583 [ 33 ] {} <Trace> RaftInstance: sent
2021.09.02 22:15:44.298700 [ 33 ] {} <Trace> RaftInstance: local log idx 28, target_commit_idx 28, quick_commit_index_ 28, state_->get_commit_idx() 27
2021.09.02 22:15:44.298774 [ 33 ] {} <Trace> RaftInstance: commit_cv_ notify (local thread)
2021.09.02 22:15:44.298883 [ 54 ] {} <Trace> RaftInstance: commit_cv_ wake up
2021.09.02 22:15:44.298998 [ 54 ] {} <Debug> RaftInstance: commit upto 28, current idx 27
2021.09.02 22:15:44.299116 [ 54 ] {} <Trace> RaftInstance: commit upto 28, current idx 28
2021.09.02 22:15:44.299340 [ 54 ] {} <Debug> RaftInstance: notify cb 28 0x7b3c000a0bb0
2021.09.02 22:15:44.299452 [ 54 ] {} <Debug> RaftInstance: DONE: commit upto 28, current idx 28
2021.09.02 22:15:44.299565 [ 54 ] {} <Trace> RaftInstance: commit_cv_ sleep
2021.09.02 22:15:44.299625 [ 30 ] {} <Debug> RaftInstance: heartbeat timeout for 2
2021.09.02 22:15:44.299730 [ 30 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:44.299836 [ 30 ] {} <Debug> RaftInstance: Server 2 is busy, skip the request
2021.09.02 22:15:44.299918 [ 36 ] {} <Trace> RaftInstance: resp of req 1 -> 2, type append_entries_request, OK
2021.09.02 22:15:44.300032 [ 36 ] {} <Debug> RaftInstance: Receive a append_entries_response message from peer 2 with Result=1, Term=1, NextIndex=29
2021.09.02 22:15:44.300107 [ 36 ] {} <Trace> RaftInstance: src: 2, dst: 1, resp->get_term(): 1
2021.09.02 22:15:44.300183 [ 36 ] {} <Trace> RaftInstance: handle append entries resp (from 2), resp.get_next_idx(): 29
2021.09.02 22:15:44.300243 [ 36 ] {} <Trace> RaftInstance: peer 2 batch size hint: 0 bytes
2021.09.02 22:15:44.300309 [ 36 ] {} <Trace> RaftInstance: peer 2, prev matched idx: 28, new matched idx: 28

Node2:

2021.09.02 22:15:36.290910 [ 22 ] {} <Debug> RaftInstance: Response back a append_entries_response message to 1 with Accepted=1, Term=1, NextIndex=28
2021.09.02 22:15:36.791241 [ 47 ] {} <Debug> RaftInstance: Receive a append_entries_request message from 1 with LastLogIndex=27, LastLogTerm=1, EntriesLength=0, CommitIndex=27 and Term=1
2021.09.02 22:15:36.791370 [ 47 ] {} <Trace> RaftInstance: from peer 1, req type: 3, req term: 1, req l idx: 27 (0), req c idx: 27, my term: 1, my role: 1
2021.09.02 22:15:36.791458 [ 47 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:36.791551 [ 47 ] {} <Trace> RaftInstance: [LOG OK] req log idx: 27, req log term: 1, my last log idx: 27, my log (27) term: 1
2021.09.02 22:15:36.791648 [ 47 ] {} <Trace> RaftInstance: local log idx 27, target_commit_idx 27, quick_commit_index_ 27, state_->get_commit_idx() 27
2021.09.02 22:15:36.791721 [ 47 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:36.791821 [ 47 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:36.791911 [ 47 ] {} <Trace> RaftInstance: batch size hint: 0 bytes
2021.09.02 22:15:36.791995 [ 47 ] {} <Debug> RaftInstance: Response back a append_entries_response message to 1 with Accepted=1, Term=1, NextIndex=28
2021.09.02 22:15:37.000331 [ 203 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.16 GiB, peak 2.16 GiB, will set to 2.16 GiB (RSS), difference: 2.08 MiB
2021.09.02 22:15:37.292195 [ 26 ] {} <Debug> RaftInstance: Receive a append_entries_request message from 1 with LastLogIndex=27, LastLogTerm=1, EntriesLength=0, CommitIndex=27 and Term=1
2021.09.02 22:15:37.292353 [ 26 ] {} <Trace> RaftInstance: from peer 1, req type: 3, req term: 1, req l idx: 27 (0), req c idx: 27, my term: 1, my role: 1
2021.09.02 22:15:37.292454 [ 26 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:37.292546 [ 26 ] {} <Trace> RaftInstance: [LOG OK] req log idx: 27, req log term: 1, my last log idx: 27, my log (27) term: 1
2021.09.02 22:15:37.292639 [ 26 ] {} <Trace> RaftInstance: local log idx 27, target_commit_idx 27, quick_commit_index_ 27, state_->get_commit_idx() 27
2021.09.02 22:15:37.292712 [ 26 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:37.292797 [ 26 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:37.292891 [ 26 ] {} <Trace> RaftInstance: batch size hint: 0 bytes
2021.09.02 22:15:37.292985 [ 26 ] {} <Debug> RaftInstance: Response back a append_entries_response message to 1 with Accepted=1, Term=1, NextIndex=28
2021.09.02 22:15:38.000335 [ 203 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.16 GiB, peak 2.16 GiB, will set to 2.17 GiB (RSS), difference: 2.57 MiB
2021.09.02 22:15:38.602053 [ 30 ] {} <Trace> RaftInstance: election timeout
2021.09.02 22:15:38.602178 [ 30 ] {} <Warning> RaftInstance: Election timeout, initiate leader election
2021.09.02 22:15:38.602331 [ 30 ] {} <Information> RaftInstance: [ELECTION TIMEOUT] current role: follower, log last term 1, state term 1, target p 3, my p 2, hb alive, pre-vote NOT done
2021.09.02 22:15:38.602424 [ 30 ] {} <Information> RaftInstance: reset RPC client for peer 1
2021.09.02 22:15:38.602973 [ 30 ] {} <Trace> RaftInstance: asio client created: 0x7b540007ff98
2021.09.02 22:15:38.603109 [ 30 ] {} <Trace> RaftInstance: asio client destroyed: 0x7b5400005a18
2021.09.02 22:15:38.603338 [ 30 ] {} <Trace> RaftInstance: 0x7b540007ff98 reconnect peer 1
2021.09.02 22:15:38.603447 [ 30 ] {} <Information> RaftInstance: [PRIORITY] will not initiate pre-vote due to priority: target 3, mine 2
2021.09.02 22:15:38.603510 [ 30 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:38.603576 [ 30 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:38.603656 [ 30 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:38.603735 [ 30 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:39.000332 [ 203 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.17 GiB, peak 2.17 GiB, will set to 2.17 GiB (RSS), difference: 3.59 MiB
2021.09.02 22:15:39.692919 [ 33 ] {} <Trace> RaftInstance: election timeout
2021.09.02 22:15:39.693048 [ 33 ] {} <Warning> RaftInstance: Election timeout, initiate leader election
2021.09.02 22:15:39.693164 [ 33 ] {} <Information> RaftInstance: [PRIORITY] decay, target 3 -> 1, mine 2
2021.09.02 22:15:39.693277 [ 33 ] {} <Information> RaftInstance: [ELECTION TIMEOUT] current role: follower, log last term 1, state term 1, target p 1, my p 2, hb dead, pre-vote NOT done
2021.09.02 22:15:39.693476 [ 33 ] {} <Warning> RaftInstance: total 1 nodes (including this node) responded for pre-vote (term 1, live 0, dead 1), at least 2 nodes should respond. failure count 1
2021.09.02 22:15:39.693621 [ 33 ] {} <Information> RaftInstance: [PRE-VOTE INIT] my id 2, my role follower, term 1, log idx 27, log term 1, priority (target 1 / mine 2)
2021.09.02 22:15:39.693751 [ 33 ] {} <Trace> RaftInstance: send req 2 -> 1, type pre_vote_request
2021.09.02 22:15:39.693853 [ 33 ] {} <Debug> RaftInstance: socket 0x7b540007ff98 to node1:44444 is not opened yet
2021.09.02 22:15:39.693984 [ 33 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:39.694056 [ 33 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:39.817211 [ 64 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushing system log, 6864 entries to flush up to offset 6864
2021.09.02 22:15:39.817494 [ 64 ] {} <Debug> SystemLog (system.asynchronous_metric_log): Creating new table system.asynchronous_metric_log for AsynchronousMetricLog
2021.09.02 22:15:39.830907 [ 64 ] {} <Debug> system.asynchronous_metric_log (b0a52b1a-ddfc-4bb6-b0a5-2b1addfc5bb6): Loading data parts
2021.09.02 22:15:39.831131 [ 64 ] {} <Debug> system.asynchronous_metric_log (b0a52b1a-ddfc-4bb6-b0a5-2b1addfc5bb6): There are no data parts
2021.09.02 22:15:39.863257 [ 64 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 19.96 GiB.
2021.09.02 22:15:39.883555 [ 64 ] {} <Trace> system.asynchronous_metric_log (b0a52b1a-ddfc-4bb6-b0a5-2b1addfc5bb6): Renaming temporary part tmp_insert_202109_1_1_0 to 202109_1_1_0.
2021.09.02 22:15:39.884482 [ 64 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushed system log up to offset 6864
2021.09.02 22:15:40.000321 [ 203 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.17 GiB, peak 2.17 GiB, will set to 2.19 GiB (RSS), difference: 18.99 MiB
2021.09.02 22:15:40.311543 [ 58 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 4 entries to flush up to offset 4
2021.09.02 22:15:40.311786 [ 58 ] {} <Debug> SystemLog (system.query_log): Creating new table system.query_log for QueryLog
2021.09.02 22:15:40.312497 [ 59 ] {} <Trace> SystemLog (system.query_thread_log): Flushing system log, 4 entries to flush up to offset 4
2021.09.02 22:15:40.312765 [ 59 ] {} <Debug> SystemLog (system.query_thread_log): Creating new table system.query_thread_log for QueryThreadLog
2021.09.02 22:15:40.315427 [ 63 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 8 entries to flush up to offset 8
2021.09.02 22:15:40.315707 [ 63 ] {} <Debug> SystemLog (system.metric_log): Creating new table system.metric_log for MetricLog
2021.09.02 22:15:40.346691 [ 59 ] {} <Debug> system.query_thread_log (ad81559b-5f28-4271-ad81-559b5f28d271): Loading data parts
2021.09.02 22:15:40.347097 [ 59 ] {} <Debug> system.query_thread_log (ad81559b-5f28-4271-ad81-559b5f28d271): There are no data parts
2021.09.02 22:15:40.363563 [ 58 ] {} <Debug> system.query_log (6cd06c7e-687f-41be-acd0-6c7e687f41be): Loading data parts
2021.09.02 22:15:40.364168 [ 58 ] {} <Debug> system.query_log (6cd06c7e-687f-41be-acd0-6c7e687f41be): There are no data parts
2021.09.02 22:15:40.365348 [ 59 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 19.96 GiB.
2021.09.02 22:15:40.378576 [ 59 ] {} <Trace> system.query_thread_log (ad81559b-5f28-4271-ad81-559b5f28d271): Renaming temporary part tmp_insert_202109_1_1_0 to 202109_1_1_0.
2021.09.02 22:15:40.381158 [ 59 ] {} <Trace> SystemLog (system.query_thread_log): Flushed system log up to offset 4
2021.09.02 22:15:40.391549 [ 58 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 19.96 GiB.
2021.09.02 22:15:40.412484 [ 58 ] {} <Trace> system.query_log (6cd06c7e-687f-41be-acd0-6c7e687f41be): Renaming temporary part tmp_insert_202109_1_1_0 to 202109_1_1_0.
2021.09.02 22:15:40.416754 [ 58 ] {} <Trace> SystemLog (system.query_log): Flushed system log up to offset 4
2021.09.02 22:15:40.421304 [ 63 ] {} <Debug> system.metric_log (767dc105-f0e1-45b5-b67d-c105f0e1c5b5): Loading data parts
2021.09.02 22:15:40.421662 [ 63 ] {} <Debug> system.metric_log (767dc105-f0e1-45b5-b67d-c105f0e1c5b5): There are no data parts
2021.09.02 22:15:40.517675 [ 63 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 19.96 GiB.
2021.09.02 22:15:40.579205 [ 63 ] {} <Trace> system.metric_log (767dc105-f0e1-45b5-b67d-c105f0e1c5b5): Renaming temporary part tmp_insert_202109_1_1_0 to 202109_1_1_0.
2021.09.02 22:15:40.594733 [ 63 ] {} <Trace> SystemLog (system.metric_log): Flushed system log up to offset 8
2021.09.02 22:15:41.000336 [ 203 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.19 GiB, peak 2.19 GiB, will set to 2.26 GiB (RSS), difference: 70.93 MiB
2021.09.02 22:15:41.517276 [ 37 ] {} <Trace> RaftInstance: election timeout
2021.09.02 22:15:41.517420 [ 37 ] {} <Warning> RaftInstance: Election timeout, initiate leader election
2021.09.02 22:15:41.517561 [ 37 ] {} <Information> RaftInstance: [PRIORITY] decay, target 1 -> 1, mine 2
2021.09.02 22:15:41.517658 [ 37 ] {} <Information> RaftInstance: [ELECTION TIMEOUT] current role: follower, log last term 1, state term 1, target p 1, my p 2, hb dead, pre-vote NOT done
2021.09.02 22:15:41.517789 [ 37 ] {} <Warning> RaftInstance: total 1 nodes (including this node) responded for pre-vote (term 1, live 0, dead 1), at least 2 nodes should respond. failure count 2
2021.09.02 22:15:41.517938 [ 37 ] {} <Information> RaftInstance: [PRE-VOTE INIT] my id 2, my role follower, term 1, log idx 27, log term 1, priority (target 1 / mine 2)
2021.09.02 22:15:41.518097 [ 37 ] {} <Warning> RaftInstance: failed to send prevote request: peer 1 (node1:44444) is busy
2021.09.02 22:15:41.518206 [ 37 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:41.518280 [ 37 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:42.000338 [ 203 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.26 GiB, peak 2.26 GiB, will set to 2.26 GiB (RSS), difference: 2.91 MiB
2021.09.02 22:15:43.000362 [ 203 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.26 GiB, peak 2.26 GiB, will set to 2.26 GiB (RSS), difference: 2.37 MiB
2021.09.02 22:15:43.042480 [ 31 ] {} <Trace> RaftInstance: election timeout
2021.09.02 22:15:43.042613 [ 31 ] {} <Warning> RaftInstance: Election timeout, initiate leader election
2021.09.02 22:15:43.042731 [ 31 ] {} <Information> RaftInstance: [PRIORITY] decay, target 1 -> 1, mine 2
2021.09.02 22:15:43.042832 [ 31 ] {} <Information> RaftInstance: [ELECTION TIMEOUT] current role: follower, log last term 1, state term 1, target p 1, my p 2, hb dead, pre-vote NOT done
2021.09.02 22:15:43.042964 [ 31 ] {} <Warning> RaftInstance: total 1 nodes (including this node) responded for pre-vote (term 1, live 0, dead 1), at least 2 nodes should respond. failure count 3
2021.09.02 22:15:43.043103 [ 31 ] {} <Information> RaftInstance: [PRE-VOTE INIT] my id 2, my role follower, term 1, log idx 27, log term 1, priority (target 1 / mine 2)
2021.09.02 22:15:43.043209 [ 31 ] {} <Warning> RaftInstance: failed to send prevote request: peer 1 (node1:44444) is busy
2021.09.02 22:15:43.043302 [ 31 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:43.043367 [ 31 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:44.000272 [ 203 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 2.26 GiB, peak 2.26 GiB, will set to 2.26 GiB (RSS), difference: 1.96 MiB
2021.09.02 22:15:44.113545 [ 35 ] {} <Trace> RaftInstance: election timeout
2021.09.02 22:15:44.113676 [ 35 ] {} <Warning> RaftInstance: Election timeout, initiate leader election
2021.09.02 22:15:44.113789 [ 35 ] {} <Information> RaftInstance: [PRIORITY] decay, target 1 -> 1, mine 2
2021.09.02 22:15:44.113893 [ 35 ] {} <Information> RaftInstance: [ELECTION TIMEOUT] current role: follower, log last term 1, state term 1, target p 1, my p 2, hb dead, pre-vote NOT done
2021.09.02 22:15:44.114025 [ 35 ] {} <Warning> RaftInstance: total 1 nodes (including this node) responded for pre-vote (term 1, live 0, dead 1), at least 2 nodes should respond. failure count 4
2021.09.02 22:15:44.114164 [ 35 ] {} <Information> RaftInstance: [PRE-VOTE INIT] my id 2, my role follower, term 1, log idx 27, log term 1, priority (target 1 / mine 2)
2021.09.02 22:15:44.114270 [ 35 ] {} <Warning> RaftInstance: failed to send prevote request: peer 1 (node1:44444) is busy
2021.09.02 22:15:44.114362 [ 35 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:44.114427 [ 35 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:44.296111 [ 40 ] {} <Debug> RaftInstance: Receive a append_entries_request message from 1 with LastLogIndex=27, LastLogTerm=1, EntriesLength=1, CommitIndex=27 and Term=1
2021.09.02 22:15:44.296240 [ 40 ] {} <Trace> RaftInstance: from peer 1, req type: 3, req term: 1, req l idx: 27 (1), req c idx: 27, my term: 1, my role: 1
2021.09.02 22:15:44.296331 [ 40 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:44.296420 [ 40 ] {} <Trace> RaftInstance: [LOG OK] req log idx: 27, req log term: 1, my last log idx: 27, my log (27) term: 1
2021.09.02 22:15:44.296504 [ 40 ] {} <Debug> RaftInstance: [INIT] log_idx: 28, count: 0, log_store_->next_slot(): 28, req.log_entries().size(): 1
2021.09.02 22:15:44.296572 [ 40 ] {} <Debug> RaftInstance: [after SKIP] log_idx: 28, count: 0
2021.09.02 22:15:44.296632 [ 40 ] {} <Debug> RaftInstance: [after OVWR] log_idx: 28, count: 0
2021.09.02 22:15:44.296686 [ 40 ] {} <Trace> RaftInstance: append at 28
2021.09.02 22:15:44.296815 [ 40 ] {} <Trace> RaftInstance: local log idx 28, target_commit_idx 27, quick_commit_index_ 27, state_->get_commit_idx() 27
2021.09.02 22:15:44.296890 [ 40 ] {} <Trace> RaftInstance: cancel existing timer
2021.09.02 22:15:44.296972 [ 40 ] {} <Trace> RaftInstance: re-schedule election timer
2021.09.02 22:15:44.297062 [ 40 ] {} <Trace> RaftInstance: batch size hint: 0 bytes
2021.09.02 22:15:44.297141 [ 40 ] {} <Debug> RaftInstance: Response back a append_entries_response message to 1 with Accepted=1, Term=1, NextIndex=29
2021.09.02 22:15:44.298653 [ 38 ] {} <Debug> RaftInstance: Receive a append_entries_request message from 1 with LastLogIndex=28, LastLogTerm=1, EntriesLength=0, CommitIndex=28 and Term=1
2021.09.02 22:15:44.298764 [ 38 ] {} <Trace> RaftInstance: from peer 1, req type: 3, req term: 1, req l idx: 28 (0), req c idx: 28, my term: 1, my role: 1
2021.09.02 22:15:44.298848 [ 38 ] {} <Trace> RaftInstance: (update) new target priority: 3
2021.09.02 22:15:44.298938 [ 38 ] {} <Trace> RaftInstance: [LOG OK] req log idx: 28, req log term: 1, my last log idx: 28, my log (28) term: 1
2021.09.02 22:15:44.299013 [ 38 ] {} <Debug> RaftInstance: trigger commit upto 28

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Sep 3, 2021

So it's a bug in Kazoo client or in our NetworkPartitioner? Keeper responded when the network became available.

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Sep 4, 2021

@Mergifyio update

@mergify
Copy link
Copy Markdown
Contributor

mergify bot commented Sep 4, 2021

Command update: success

Branch has been successfully updated

@alesapin alesapin merged commit 8d67a34 into master Sep 6, 2021
@alesapin alesapin deleted the add_test_for_two_nodes_configuration branch September 6, 2021 10:44
@alexey-milovidov alexey-milovidov mentioned this pull request Nov 24, 2021
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

pr-not-for-changelog This PR should not be mentioned in the changelog

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@alesapin @robot-clickhouse