Failed test/int/test_couple.py::test_deactivation
Кажется это флаки тест.
- https://git.picodata.io/picodata/picodata/picodata/-/jobs/27115
- https://git.picodata.io/picodata/picodata/picodata/-/jobs/27016
- https://git.picodata.io/picodata/picodata/picodata/-/jobs/27404
Test log
=================================== FAILURES ===================================
______________________________ test_deactivation _______________________________
[gw0] linux -- Python 3.10.4 /builds/picodata/picodata/picodata/.venv/bin/python
cluster2 = Cluster("127.0.0.1:3300", n=2)
def test_deactivation(cluster2: Cluster):
i1, i2 = cluster2.instances
def is_voter_is_active(instance: Instance, raft_id):
return tuple(
instance.eval(
"""
raft_id = ...
health = box.space.raft_group.index.raft_id:get(raft_id).health
is_active = health == 'Online'
voters = box.space.raft_state:get('voters').value
for _, voter in pairs(voters) do
if voter == raft_id then
return { true, is_active }
end
end
return { false, is_active }
""",
raft_id,
)
)
assert is_voter_is_active(i1, i1.raft_id) == (True, True)
assert is_voter_is_active(i2, i2.raft_id) == (True, True)
i2.terminate()
assert is_voter_is_active(i1, i1.raft_id) == (True, True)
assert is_voter_is_active(i1, i2.raft_id) == (False, False)
i2.start()
i2.wait_ready()
assert is_voter_is_active(i1, i1.raft_id) == (True, True)
assert is_voter_is_active(i2, i2.raft_id) == (True, True)
i1.terminate()
> assert is_voter_is_active(i2, i1.raft_id) == (False, False)
E assert == failed. [pytest-clarity diff shown]
E
E LHS vs RHS shown below
E
E (True, True)
E (False, False)
E
test/int/test_couple.py:145: AssertionError
---------------------------- Captured stdout setup -----------------------------
i2 | [supervisor:52982] running StartDiscover
i1 | [supervisor:52979] running StartDiscover
i1 | [supervisor:52979] subprocess finished: Ok(Exited(Pid(52986), 0))
i1 | [supervisor:52979] subprocess requested rebootstrap
i1 | [supervisor] removing file: /tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i1/00000000000000000000.snap
i1 | [supervisor] removing file: /tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i1/00000000000000000000.xlog
i1 | [supervisor:52979] running StartBoot
i2 | [supervisor:52982] subprocess finished: Ok(Exited(Pid(52987), 0))
i2 | [supervisor:52982] subprocess requested rebootstrap
i2 | [supervisor] removing file: /tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000000.snap
i2 | [supervisor] removing file: /tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000000.xlog
i2 | [supervisor:52982] running StartJoin { leader_address: "127.0.0.1:3301" }
---------------------------- Captured stderr setup -----------------------------
Instance(i1, listen=127.0.0.1:3301) starting...
Instance(i2, listen=127.0.0.1:3302) starting...
i1 | >>>>> start_discover()
i2 | >>>>> start_discover()
i1 | 2022-07-22 11:16:40.062 [52986] main/103/interactive I> Tarantool 2.10.0-29-g1ec2a9d
i1 | 2022-07-22 11:16:40.063 [52986] main/103/interactive I> log level 5
i1 | 2022-07-22 11:16:40.063 [52986] main/103/interactive I> wal/engine cleanup is paused
i2 | 2022-07-22 11:16:40.062 [52987] main/103/interactive I> Tarantool 2.10.0-29-g1ec2a9d
i2 | 2022-07-22 11:16:40.063 [52987] main/103/interactive I> log level 5
i2 | 2022-07-22 11:16:40.063 [52987] main/103/interactive I> wal/engine cleanup is paused
i1 | 2022-07-22 11:16:40.063 [52986] main/103/interactive I> mapping 33554432 bytes for memtx tuple arena...
i2 | 2022-07-22 11:16:40.063 [52987] main/103/interactive I> mapping 33554432 bytes for memtx tuple arena...
i1 | 2022-07-22 11:16:40.063 [52986] main/103/interactive I> Actual slab_alloc_factor calculated on the basis of desired slab_alloc_factor = 1.044274
i2 | 2022-07-22 11:16:40.063 [52987] main/103/interactive I> Actual slab_alloc_factor calculated on the basis of desired slab_alloc_factor = 1.044274
i1 | 2022-07-22 11:16:40.063 [52986] main/103/interactive I> mapping 134217728 bytes for vinyl tuple arena...
i2 | 2022-07-22 11:16:40.063 [52987] main/103/interactive I> mapping 134217728 bytes for vinyl tuple arena...
i1 | 2022-07-22 11:16:40.079 [52986] main/103/interactive I> update replication_synchro_quorum = 1
i1 | 2022-07-22 11:16:40.079 [52986] main/103/interactive I> instance uuid afef1198-1331-4b1a-a46d-9cd45a11a374
i1 | 2022-07-22 11:16:40.079 [52986] main/103/interactive I> initializing an empty data directory
i2 | 2022-07-22 11:16:40.079 [52987] main/103/interactive I> update replication_synchro_quorum = 1
i2 | 2022-07-22 11:16:40.079 [52987] main/103/interactive I> instance uuid 95b84f97-67e9-4a9d-a120-1bbe6601db8e
i2 | 2022-07-22 11:16:40.079 [52987] main/103/interactive I> initializing an empty data directory
i1 | 2022-07-22 11:16:40.116 [52986] main/103/interactive I> assigned id 1 to replica afef1198-1331-4b1a-a46d-9cd45a11a374
i1 | 2022-07-22 11:16:40.116 [52986] main/103/interactive I> update replication_synchro_quorum = 1
i1 | 2022-07-22 11:16:40.116 [52986] main/103/interactive I> cluster uuid 08a060c5-e39c-4270-aa46-c2ea36d17826
i2 | 2022-07-22 11:16:40.117 [52987] main/103/interactive I> assigned id 1 to replica 95b84f97-67e9-4a9d-a120-1bbe6601db8e
i2 | 2022-07-22 11:16:40.117 [52987] main/103/interactive I> update replication_synchro_quorum = 1
i2 | 2022-07-22 11:16:40.117 [52987] main/103/interactive I> cluster uuid 7f3712fc-8b53-4a05-bd2a-8dca153538e4
i1 | 2022-07-22 11:16:40.120 [52986] snapshot/101/main I> saving snapshot `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i1/00000000000000000000.snap.inprogress'
i2 | 2022-07-22 11:16:40.121 [52987] snapshot/101/main I> saving snapshot `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000000.snap.inprogress'
i2 | 2022-07-22 11:16:40.126 [52987] snapshot/101/main I> done
i1 | 2022-07-22 11:16:40.126 [52986] snapshot/101/main I> done
i2 | 2022-07-22 11:16:40.126 [52987] main/103/interactive I> RAFT: fencing enabled
i2 | 2022-07-22 11:16:40.126 [52987] main/103/interactive I> ready to accept requests
i2 | 2022-07-22 11:16:40.126 [52987] main/105/gc I> wal/engine cleanup is resumed
i1 | 2022-07-22 11:16:40.127 [52986] main/103/interactive I> RAFT: fencing enabled
i1 | 2022-07-22 11:16:40.127 [52986] main/103/interactive I> ready to accept requests
i1 | 2022-07-22 11:16:40.127 [52986] main/105/gc I> wal/engine cleanup is resumed
i2 | 2022-07-22 11:16:40.127 [52987] main/103/interactive I> set 'log_level' configuration option to 5
i1 | 2022-07-22 11:16:40.127 [52986] main/103/interactive I> set 'log_level' configuration option to 5
i2 | 2022-07-22 11:16:40.127 [52987] main/103/interactive I> set 'feedback_enabled' configuration option to false
i2 | 2022-07-22 11:16:40.127 [52987] main/103/interactive I> set 'log_format' configuration option to "plain"
i2 | 2022-07-22 11:16:40.127 [52987] main/103/interactive I> set 'memtx_memory' configuration option to 33554432
i2 | 2022-07-22 11:16:40.127 [52987] main/103/interactive I> set 'replication_connect_quorum' configuration option to 32
i2 | 2022-07-22 11:16:40.127 [52987] main/103/interactive I> set 'replication' configuration option to []
i1 | 2022-07-22 11:16:40.127 [52986] main/103/interactive I> set 'feedback_enabled' configuration option to false
i1 | 2022-07-22 11:16:40.127 [52986] main/103/interactive I> set 'log_format' configuration option to "plain"
i1 | 2022-07-22 11:16:40.127 [52986] main/103/interactive I> set 'memtx_memory' configuration option to 33554432
i1 | 2022-07-22 11:16:40.127 [52986] main/103/interactive I> set 'replication_connect_quorum' configuration option to 32
i1 | 2022-07-22 11:16:40.127 [52986] main/103/interactive I> set 'replication' configuration option to []
i1 | 2022-07-22 11:16:40.127 [52986] main/106/checkpoint_daemon I> scheduled next checkpoint for Fri Jul 22 13:07:29 2022
i2 | 2022-07-22 11:16:40.127 [52987] main/106/checkpoint_daemon I> scheduled next checkpoint for Fri Jul 22 12:34:38 2022
i2 | 2022-07-22 11:16:40.132 [52987] main/103/interactive I> tx_binary: bound to 127.0.0.1:3302
i2 | 2022-07-22 11:16:40.132 [52987] main/103/interactive I> set 'listen' configuration option to "127.0.0.1:3302"
i2 | 2022-07-22 11:16:40.133 [52987] main/103/interactive tarantool.rs:242 W> net_box_call failed: IO error: Connection refused (os error 111), fn: .proc_discover, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:40.135 [52986] main/103/interactive I> tx_binary: bound to 127.0.0.1:3301
i1 | 2022-07-22 11:16:40.135 [52986] main/103/interactive I> set 'listen' configuration option to "127.0.0.1:3301"
i1 | >>>>> start_boot()
i1 | 2022-07-22 11:16:40.467 [53000] main/103/interactive I> Tarantool 2.10.0-29-g1ec2a9d
i1 | 2022-07-22 11:16:40.467 [53000] main/103/interactive I> log level 5
i1 | 2022-07-22 11:16:40.467 [53000] main/103/interactive I> wal/engine cleanup is paused
i1 | 2022-07-22 11:16:40.467 [53000] main/103/interactive I> mapping 33554432 bytes for memtx tuple arena...
i1 | 2022-07-22 11:16:40.467 [53000] main/103/interactive I> Actual slab_alloc_factor calculated on the basis of desired slab_alloc_factor = 1.044274
i1 | 2022-07-22 11:16:40.467 [53000] main/103/interactive I> mapping 134217728 bytes for vinyl tuple arena...
i1 | 2022-07-22 11:16:40.482 [53000] main/103/interactive I> update replication_synchro_quorum = 1
i1 | 2022-07-22 11:16:40.482 [53000] main/103/interactive I> instance uuid 68d4a766-4144-3248-aeb4-e212356716e4
i1 | 2022-07-22 11:16:40.482 [53000] main/103/interactive I> initializing an empty data directory
i1 | 2022-07-22 11:16:40.518 [53000] main/103/interactive I> assigned id 1 to replica 68d4a766-4144-3248-aeb4-e212356716e4
i1 | 2022-07-22 11:16:40.518 [53000] main/103/interactive I> update replication_synchro_quorum = 1
i1 | 2022-07-22 11:16:40.518 [53000] main/103/interactive I> cluster uuid e0df68c5-e7f9-395f-86b3-30ad9e1b7b07
i1 | 2022-07-22 11:16:40.521 [53000] snapshot/101/main I> saving snapshot `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i1/00000000000000000000.snap.inprogress'
i1 | 2022-07-22 11:16:40.527 [53000] snapshot/101/main I> done
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> RAFT: fencing enabled
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> ready to accept requests
i1 | 2022-07-22 11:16:40.528 [53000] main/105/gc I> wal/engine cleanup is resumed
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> set 'log_level' configuration option to 5
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> set 'feedback_enabled' configuration option to false
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> set 'log_format' configuration option to "plain"
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> set 'memtx_memory' configuration option to 33554432
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> set 'instance_uuid' configuration option to "68d4a766-4144-3248-aeb4-e212356716e4"
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> set 'replication_connect_quorum' configuration option to 32
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> set 'replication' configuration option to []
i1 | 2022-07-22 11:16:40.528 [53000] main/106/checkpoint_daemon I> scheduled next checkpoint for Fri Jul 22 13:04:54 2022
i1 | 2022-07-22 11:16:40.528 [53000] main/103/interactive I> set 'replicaset_uuid' configuration option to "e0df68c5-e7f9-395f-86b3-30ad9e1b7b07"
i1 | 2022-07-22 11:16:40.536 [53000] main/103/interactive I> >>>>> postjoin()
i1 | 2022-07-22 11:16:40.536 [53000] main/103/interactive I> leaving orphan mode
i1 | 2022-07-22 11:16:40.536 [53000] main/103/interactive I> set 'replication_connect_quorum' configuration option to 0
i1 | 2022-07-22 11:16:40.537 [53000] main/103/interactive I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 1
i1 | 2022-07-22 11:16:40.537 [53000] main/103/interactive I> became follower at term 1, term: 1, raft_id: 1
i1 | 2022-07-22 11:16:40.537 [53000] main/103/interactive I> newRaft, peers: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, last term: 1, last index: 3, applied: 0, commit: 3, term: 1, raft_id: 1
i1 | 2022-07-22 11:16:40.537 [53000] main/103/interactive I> RawNode created with id 1., id: 1, raft_id: 1
i1 | 2022-07-22 11:16:40.539 [53000] main/111/raft_main_loop I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 1
i1 | 2022-07-22 11:16:40.539 [53000] main/103/interactive I> this is the only vorer in cluster, triggering election immediately
i1 | 2022-07-22 11:16:40.539 [53000] main/111/raft_main_loop I> connecting to 1 replicas
i1 | 2022-07-22 11:16:40.540 [53000] main/111/raft_main_loop C> failed to connect to 1 out of 1 replicas
i1 | 2022-07-22 11:16:40.540 [53000] main/111/raft_main_loop I> leaving orphan mode
i1 | 2022-07-22 11:16:40.540 [53000] main/111/raft_main_loop I> set 'replication' configuration option to ["127.0.0.1:3301"]
i1 | 2022-07-22 11:16:40.540 [53000] main/111/raft_main_loop I> starting a new election, term: 1, raft_id: 1
i1 | 2022-07-22 11:16:40.540 [53000] main/111/raft_main_loop I> became pre-candidate at term 1, term: 1, raft_id: 1
i1 | 2022-07-22 11:16:40.540 [53000] main/111/raft_main_loop I> became candidate at term 2, term: 2, raft_id: 1
i1 | 2022-07-22 11:16:40.542 [53000] main/111/raft_main_loop I> became leader at term 2, term: 2, raft_id: 1
i1 | 2022-07-22 11:16:40.543 [53000] main/115/applier/127.0.0.1:3301 I> can't connect to master
i1 | 2022-07-22 11:16:40.543 [53000] main/115/applier/127.0.0.1:3301 coio.c:83 E> SocketError: connect, called on fd 22, aka 127.0.0.1:36662: Connection refused
i1 | 2022-07-22 11:16:40.543 [53000] main/115/applier/127.0.0.1:3301 I> will retry every 1.00 second
i1 | 2022-07-22 11:16:40.543 [53000] main/103/interactive I> tx_binary: bound to 127.0.0.1:3301
i1 | 2022-07-22 11:16:40.543 [53000] main/103/interactive I> set 'listen' configuration option to "127.0.0.1:3301"
i1 | 2022-07-22 11:16:40.543 [53000] main/103/interactive I> leaving orphan mode
i1 | 2022-07-22 11:16:40.543 [53000] main/103/interactive I> set 'replication' configuration option to []
i1 | 2022-07-22 11:16:40.543 [53000] main/103/interactive I> Read barrier aquired, raft is ready
i1 | 2022-07-22 11:16:40.544 [53000] main/103/interactive I> connecting to 1 replicas
i1 | 2022-07-22 11:16:40.544 [53000] main/103/interactive C> failed to connect to 1 out of 1 replicas
i1 | 2022-07-22 11:16:40.544 [53000] main/103/interactive I> leaving orphan mode
i1 | 2022-07-22 11:16:40.544 [53000] main/103/interactive I> set 'replication' configuration option to ["127.0.0.1:3301"]
i1 | 2022-07-22 11:16:40.544 [53000] main/103/interactive I> initiating self-activation of "i1"
i1 | 2022-07-22 11:16:40.548 [53000] main/117/applier/127.0.0.1:3301 I> remote master 68d4a766-4144-3248-aeb4-e212356716e4 at 127.0.0.1:3301 running Tarantool 2.10.0
i1 | 2022-07-22 11:16:40.549 [53000] main/117/applier/127.0.0.1:3301 I> leaving orphan mode
i1 | 2022-07-22 11:16:40.551 [53000] main I> entering the event loop
Instance(i1, listen=127.0.0.1:3301) is ready
i2 | >>>>> start_join(127.0.0.1:3301)
i1 | 2022-07-22 11:16:40.665 [53000] main/111/raft_main_loop I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1, 2} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 1
i1 | 2022-07-22 11:16:40.666 [53000] main/112/raft_conf_change_loop I> conf_change processed
i2 | 2022-07-22 11:16:40.667 [53006] main/103/interactive I> Tarantool 2.10.0-29-g1ec2a9d
i2 | 2022-07-22 11:16:40.667 [53006] main/103/interactive I> log level 5
i2 | 2022-07-22 11:16:40.667 [53006] main/103/interactive I> wal/engine cleanup is paused
i2 | 2022-07-22 11:16:40.667 [53006] main/103/interactive I> mapping 33554432 bytes for memtx tuple arena...
i2 | 2022-07-22 11:16:40.668 [53006] main/103/interactive I> Actual slab_alloc_factor calculated on the basis of desired slab_alloc_factor = 1.044274
i2 | 2022-07-22 11:16:40.668 [53006] main/103/interactive I> mapping 134217728 bytes for vinyl tuple arena...
i2 | 2022-07-22 11:16:40.683 [53006] main/103/interactive I> update replication_synchro_quorum = 1
i2 | 2022-07-22 11:16:40.683 [53006] main/103/interactive I> instance uuid 24c4ac5f-4981-3441-879c-aee1edb608a6
i2 | 2022-07-22 11:16:40.683 [53006] main/103/interactive I> tx_binary: bound to 127.0.0.1:3302
i2 | 2022-07-22 11:16:40.684 [53006] main/103/interactive I> connecting to 1 replicas
i2 | 2022-07-22 11:16:40.687 [53006] main/113/applier/127.0.0.1:3302 I> remote master 24c4ac5f-4981-3441-879c-aee1edb608a6 at 127.0.0.1:3302 running Tarantool 2.10.0
i2 | 2022-07-22 11:16:40.687 [53006] main/103/interactive I> connected to 1 replicas
i2 | 2022-07-22 11:16:40.687 [53006] main/103/interactive I> initializing an empty data directory
i2 | 2022-07-22 11:16:40.725 [53006] main/103/interactive I> assigned id 1 to replica 24c4ac5f-4981-3441-879c-aee1edb608a6
i2 | 2022-07-22 11:16:40.726 [53006] main/103/interactive I> update replication_synchro_quorum = 1
i2 | 2022-07-22 11:16:40.726 [53006] main/103/interactive I> cluster uuid eff4449e-feb2-3d73-87bc-75807cb23191
i2 | 2022-07-22 11:16:40.730 [53006] snapshot/101/main I> saving snapshot `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000000.snap.inprogress'
i2 | 2022-07-22 11:16:40.735 [53006] snapshot/101/main I> done
i2 | 2022-07-22 11:16:40.736 [53006] main/103/interactive I> RAFT: fencing enabled
i2 | 2022-07-22 11:16:40.736 [53006] main/103/interactive I> ready to accept requests
i2 | 2022-07-22 11:16:40.736 [53006] main/107/gc I> wal/engine cleanup is resumed
i2 | 2022-07-22 11:16:40.736 [53006] main/113/applier/127.0.0.1:3302 I> leaving orphan mode
i2 | 2022-07-22 11:16:40.736 [53006] main/103/interactive I> set 'log_level' configuration option to 5
i2 | 2022-07-22 11:16:40.737 [53006] main/103/interactive I> set 'feedback_enabled' configuration option to false
i2 | 2022-07-22 11:16:40.737 [53006] main/103/interactive I> set 'log_format' configuration option to "plain"
i2 | 2022-07-22 11:16:40.737 [53006] main/103/interactive I> set 'memtx_memory' configuration option to 33554432
i2 | 2022-07-22 11:16:40.737 [53006] main/103/interactive I> set 'instance_uuid' configuration option to "24c4ac5f-4981-3441-879c-aee1edb608a6"
i2 | 2022-07-22 11:16:40.737 [53006] main/103/interactive I> set 'listen' configuration option to "127.0.0.1:3302"
i2 | 2022-07-22 11:16:40.737 [53006] main/103/interactive I> set 'replication_connect_quorum' configuration option to 32
i2 | 2022-07-22 11:16:40.737 [53006] main/103/interactive I> set 'replication' configuration option to ["127.0.0.1:3302"]
i2 | 2022-07-22 11:16:40.737 [53006] main/108/checkpoint_daemon I> scheduled next checkpoint for Fri Jul 22 12:43:53 2022
i2 | 2022-07-22 11:16:40.737 [53006] main/103/interactive I> set 'replicaset_uuid' configuration option to "eff4449e-feb2-3d73-87bc-75807cb23191"
i2 | 2022-07-22 11:16:40.742 [53006] main/103/interactive I> >>>>> postjoin()
i2 | 2022-07-22 11:16:40.743 [53006] main/103/interactive I> leaving orphan mode
i2 | 2022-07-22 11:16:40.743 [53006] main/103/interactive I> set 'replication_connect_quorum' configuration option to 0
i2 | 2022-07-22 11:16:40.743 [53006] main/103/interactive I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 2
i2 | 2022-07-22 11:16:40.743 [53006] main/103/interactive I> became follower at term 0, term: 0, raft_id: 2
i2 | 2022-07-22 11:16:40.743 [53006] main/103/interactive I> newRaft, peers: Configuration { incoming: Configuration { voters: {} }, outgoing: Configuration { voters: {} } }, last term: 0, last index: 0, applied: 0, commit: 0, term: 0, raft_id: 2
i2 | 2022-07-22 11:16:40.743 [53006] main/103/interactive I> RawNode created with id 2., id: 2, raft_id: 2
i2 | 2022-07-22 11:16:40.767 [53006] main/114/raft_main_loop I> received a message with higher term from 1, msg type: MsgAppend, message_term: 2, term: 0, from: 1, raft_id: 2
i2 | 2022-07-22 11:16:40.767 [53006] main/114/raft_main_loop I> became follower at term 2, term: 2, raft_id: 2
i2 | 2022-07-22 11:16:40.778 [53006] main/114/raft_main_loop I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 2
i2 | 2022-07-22 11:16:40.778 [53006] main/114/raft_main_loop I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1, 2} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 2
i2 | 2022-07-22 11:16:40.779 [53006] main/103/interactive I> Read barrier aquired, raft is ready
i2 | 2022-07-22 11:16:40.780 [53006] main/103/interactive I> initiating self-activation of "i2"
i2 | 2022-07-22 11:16:40.784 [53006] main I> entering the event loop
Instance(i2, listen=127.0.0.1:3302) is ready
=================== Cluster("127.0.0.1:3300", n=2) deployed ====================
----------------------------- Captured stdout call -----------------------------
i2 | [supervisor:52982] got signal 15
i2 | [supervisor:52982] subprocess finished: Ok(Exited(Pid(53006), 0))
i2 | [supervisor:53075] running StartDiscover
i1 | [supervisor:52979] got signal 15
i1 | [supervisor:52979] subprocess finished: Ok(Exited(Pid(53000), 0))
----------------------------- Captured stderr call -----------------------------
i2 | 2022-07-22 11:16:41.013 [53006] main/125/iproto.shutdown I> tx_binary: stopped
i1 | 2022-07-22 11:16:41.018 [53000] main/111/raft_main_loop I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, learners: {2}, learners_next: {}, auto_leave: false }, raft_id: 1
i1 | 2022-07-22 11:16:41.018 [53000] main/112/raft_conf_change_loop I> conf_change processed
i2 | 2022-07-22 11:16:41.018 [53006] main/114/raft_main_loop I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, learners: {2}, learners_next: {}, auto_leave: false }, raft_id: 2
i2 | 2022-07-22 11:16:44.013 [53006] main/102/on_shutdown fiber.c:671 E> TimedOut: timed out
Instance(i2, listen=127.0.0.1:3302) terminated: rc = 0
Instance(i2, listen=127.0.0.1:3302) starting...
i2 | >>>>> start_discover()
i2 | 2022-07-22 11:16:44.189 [53079] main/103/interactive I> Tarantool 2.10.0-29-g1ec2a9d
i2 | 2022-07-22 11:16:44.189 [53079] main/103/interactive I> log level 5
i2 | 2022-07-22 11:16:44.189 [53079] main/103/interactive I> wal/engine cleanup is paused
i2 | 2022-07-22 11:16:44.193 [53079] main/103/interactive I> mapping 33554432 bytes for memtx tuple arena...
i2 | 2022-07-22 11:16:44.193 [53079] main/103/interactive I> Actual slab_alloc_factor calculated on the basis of desired slab_alloc_factor = 1.044274
i2 | 2022-07-22 11:16:44.194 [53079] main/103/interactive I> mapping 134217728 bytes for vinyl tuple arena...
i2 | 2022-07-22 11:16:44.194 [53079] main/103/interactive I> Recovering snapshot with schema version 2.10.1
i2 | 2022-07-22 11:16:44.206 [53079] main/103/interactive I> update replication_synchro_quorum = 1
i2 | 2022-07-22 11:16:44.206 [53079] main/103/interactive I> instance uuid 24c4ac5f-4981-3441-879c-aee1edb608a6
i2 | 2022-07-22 11:16:44.207 [53079] main/103/interactive I> instance vclock {0: 60, 1: 16}
i2 | 2022-07-22 11:16:44.208 [53079] main/103/interactive I> recovery start
i2 | 2022-07-22 11:16:44.208 [53079] main/103/interactive I> recovering from `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000000.snap'
i2 | 2022-07-22 11:16:44.230 [53079] main/103/interactive I> cluster uuid eff4449e-feb2-3d73-87bc-75807cb23191
i2 | 2022-07-22 11:16:44.243 [53079] main/103/interactive I> assigned id 1 to replica 24c4ac5f-4981-3441-879c-aee1edb608a6
i2 | 2022-07-22 11:16:44.243 [53079] main/103/interactive I> update replication_synchro_quorum = 1
i2 | 2022-07-22 11:16:44.243 [53079] main/103/interactive I> recover from `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000000.xlog'
i2 | 2022-07-22 11:16:44.245 [53079] main/103/interactive I> done `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000000.xlog'
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> recover from `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000076.xlog'
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> done `/tmp/pytest-of-root/pytest-0/popen-gw0/test_deactivation0/i2/00000000000000000076.xlog'
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> Building secondary indexes in space 'raft_group'...
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> Adding 2 keys to TREE index 'raft_id' ...
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> Adding 2 keys to TREE index 'replicaset_id' ...
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> Space 'raft_group': done
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> RAFT: fencing enabled
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> ready to accept requests
i2 | 2022-07-22 11:16:44.246 [53079] main/103/interactive I> leaving orphan mode
i2 | 2022-07-22 11:16:44.246 [53079] main/105/gc I> wal/engine cleanup is resumed
i2 | 2022-07-22 11:16:44.247 [53079] main/103/interactive I> set 'log_level' configuration option to 5
i2 | 2022-07-22 11:16:44.247 [53079] main/103/interactive I> set 'feedback_enabled' configuration option to false
i2 | 2022-07-22 11:16:44.247 [53079] main/103/interactive I> set 'log_format' configuration option to "plain"
i2 | 2022-07-22 11:16:44.247 [53079] main/103/interactive I> set 'memtx_memory' configuration option to 33554432
i2 | 2022-07-22 11:16:44.247 [53079] main/103/interactive I> set 'replication_connect_quorum' configuration option to 32
i2 | 2022-07-22 11:16:44.247 [53079] main/103/interactive I> set 'replication' configuration option to []
i2 | 2022-07-22 11:16:44.247 [53079] main/106/checkpoint_daemon I> scheduled next checkpoint for Fri Jul 22 12:57:57 2022
i2 | 2022-07-22 11:16:44.249 [53079] main/103/interactive I> tx_binary: bound to 127.0.0.1:3302
i2 | 2022-07-22 11:16:44.249 [53079] main/103/interactive I> set 'listen' configuration option to "127.0.0.1:3302"
i2 | 2022-07-22 11:16:44.250 [53079] main/103/interactive I> >>>>> postjoin()
i2 | 2022-07-22 11:16:44.250 [53079] main/103/interactive I> leaving orphan mode
i2 | 2022-07-22 11:16:44.250 [53079] main/103/interactive I> set 'replication_connect_quorum' configuration option to 0
i2 | 2022-07-22 11:16:44.250 [53079] main/103/interactive I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, learners: {2}, learners_next: {}, auto_leave: false }, raft_id: 2
i2 | 2022-07-22 11:16:44.250 [53079] main/103/interactive I> became follower at term 2, term: 2, raft_id: 2
i2 | 2022-07-22 11:16:44.251 [53079] main/103/interactive I> newRaft, peers: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, last term: 2, last index: 10, applied: 10, commit: 10, term: 2, raft_id: 2
i2 | 2022-07-22 11:16:44.251 [53079] main/103/interactive I> RawNode created with id 2., id: 2, raft_id: 2
i2 | 2022-07-22 11:16:44.448 [53079] main/103/interactive I> Read barrier aquired, raft is ready
i2 | 2022-07-22 11:16:44.448 [53079] main/103/interactive I> connecting to 1 replicas
i2 | 2022-07-22 11:16:44.448 [53079] main/103/interactive C> failed to connect to 1 out of 1 replicas
i2 | 2022-07-22 11:16:44.449 [53079] main/103/interactive I> leaving orphan mode
i2 | 2022-07-22 11:16:44.449 [53079] main/103/interactive I> set 'replication' configuration option to ["127.0.0.1:3302"]
i2 | 2022-07-22 11:16:44.449 [53079] main/103/interactive I> initiating self-activation of "i2"
i2 | 2022-07-22 11:16:44.449 [53079] main/118/applier/127.0.0.1:3302 I> remote master 24c4ac5f-4981-3441-879c-aee1edb608a6 at 127.0.0.1:3302 running Tarantool 2.10.0
i2 | 2022-07-22 11:16:44.450 [53079] main/118/applier/127.0.0.1:3302 I> leaving orphan mode
i2 | 2022-07-22 11:16:44.451 [53079] main I> entering the event loop
i1 | 2022-07-22 11:16:44.453 [53000] main/111/raft_main_loop I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1, 2} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 1
i1 | 2022-07-22 11:16:44.453 [53000] main/112/raft_conf_change_loop I> conf_change processed
i2 | 2022-07-22 11:16:44.454 [53079] main/111/raft_main_loop I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1, 2} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 2
Instance(i2, listen=127.0.0.1:3302) is ready
i1 | 2022-07-22 11:16:44.499 [53000] main/131/iproto.shutdown I> tx_binary: stopped
i1 | 2022-07-22 11:16:44.499 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection reset by peer (os error 104), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:44.799 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:45.100 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:45.400 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:45.700 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:46.001 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:46.301 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:46.601 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:46.901 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:47.201 [53000] main/128/trigger_fiber0 failover.rs:44 W> failed to deactivate myself: IO error: Connection refused (os error 111), fn: .raft_update_peer, peer: 127.0.0.1:3301
i1 | 2022-07-22 11:16:47.499 [53000] main/102/on_shutdown fiber.c:671 E> TimedOut: timed out
Instance(i1, listen=127.0.0.1:3301) terminated: rc = 0
--------------------------- Captured stderr teardown ---------------------------
Instance(i2, listen=127.0.0.1:
3302) killed
=========================== short test summary info ============================
FAILED test/int/test_couple.py::test_deactivation - assert == failed. [pytest...
======================== 1 failed, 26 passed in 48.05s =========================
Cleaning up project directory and file based variables 00:02