test: flaky replication/election_basic.test.lua test

[avtikhon]

Tarantool version:
Tarantool 2.6.0-129-gd25ecab48
Target: FreeBSD-amd64-RelWithDebInfo
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=OFF
Compiler: /usr/bin/cc /usr/bin/c++
C_FLAGS: -Wno-unknown-pragmas -fexceptions -funwind-tables -fno-common -std=c11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-gnu-alignof-expression -Werror
CXX_FLAGS: -Wno-unknown-pragmas -fexceptions -funwind-tables -fno-common -std=c++11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Werror

OS version:
All

Bug description:
Issue appeared on 01.10.2020 nightly testing after its initial commit:
https://gitlab.com/tarantool/tarantool/-/commit/cf799645119907d646984ffe52624a8740e6ecbe

1a.
https://gitlab.com/tarantool/tarantool/-/jobs/766596448#L5190
https://gitlab.com/tarantool/tarantool/-/jobs/766800052#L4874

artifacts.zip

results file checksum: 9c27e4fbc1acfb49f3bd1ab05423bf72

[005] --- replication/election_basic.result	Thu Oct  1 04:10:17 2020
[005] +++ replication/election_basic.reject	Fri May  8 08:21:01 2020
[005] @@ -261,11 +261,11 @@
[005]   | ...
[005]  assert(r1_leader ~= 0)
[005]   | ---
[005] - | - true
[005] + | - error: assertion failed!
[005]   | ...
[005]  assert(r1_leader == r2_leader)
[005]   | ---
[005] - | - true
[005] + | - error: assertion failed!
[005]   | ...
[005]  
[005]  test_run:cmd(string.format('start server %s', leader_name))
[005] 

1b.
https://gitlab.com/tarantool/tarantool/-/jobs/771464767#L5755

artifacts.zip

results file checksum: 69d75832017bb140887fd9c7b1d43cf1

[035] --- replication/election_basic.result	Sun Oct  4 04:23:22 2020
[035] +++ replication/election_basic.reject	Fri May  8 08:23:57 2020
[035] @@ -265,7 +265,7 @@
[035]   | ...
[035]  assert(r1_leader == r2_leader)
[035]   | ---
[035] - | - true
[035] + | - error: assertion failed!
[035]   | ...
[035]  
[035]  test_run:cmd(string.format('start server %s', leader_name))
[035] 

2a.
https://gitlab.com/tarantool/tarantool/-/jobs/771339455#L6012

artifacts.zip

results file checksum: 42ff9f71a7ad2de4b379ec61707b0761

Segmentation fault
  code: 0
  addr: 0x0
  context: 0x1069ffca0
  siginfo: 0x1069ffc38
Current time: 1601764725
Please file a bug at http://github.com/tarantool/tarantool/issues
Attempting backtrace... Note: since the server has already crashed, 
this may fail as well
#0  0x10434f579 in print_backtrace+9
#1  0x1048bd0d1 in _ZL12sig_fatal_cbiP9__siginfoPv+141
#2  0x7fff675855fd in _sigtramp+1d
[076] replication/election_basic.test.lua             vinyl           
[076] 
[076] [Instance "election_replica1" killed by signal: 6 (SIGABRT)]
[076] [ fail ]

2b.
https://gitlab.com/tarantool/tarantool/-/jobs/766596435#L3822
https://gitlab.com/tarantool/tarantool/-/jobs/766691559#L5207

artifacts.zip

results file checksum: 2870483307db27542796a3b2cf76a9f1

[006] replication/election_basic.test.lua             vinyl           
[006] TarantoolInpector.handle() received the following error:
[006] Traceback (most recent call last):
[006]   File "/builds/e94Uc7Js/0/tarantool/tarantool/test-run/lib/inspector.py", line 94, in handle
[006]     result = self.parser.parse_preprocessor(line)
[006]   File "/builds/e94Uc7Js/0/tarantool/tarantool/test-run/lib/preprocessor.py", line 73, in parse_preprocessor
[006]     return self.lua_eval(name, expr[1:-1])
[006]   File "/builds/e94Uc7Js/0/tarantool/tarantool/test-run/lib/preprocessor.py", line 392, in lua_eval
[006]     result = yaml.safe_load(result)
[006]   File "/usr/lib/python2.7/dist-packages/yaml/__init__.py", line 93, in safe_load
[006]     return load(stream, SafeLoader)
[006]   File "/usr/lib/python2.7/dist-packages/yaml/__init__.py", line 69, in load
[006]     loader = Loader(stream)
[006]   File "/usr/lib/python2.7/dist-packages/yaml/loader.py", line 24, in __init__
[006]     Reader.__init__(self, stream)
[006]   File "/usr/lib/python2.7/dist-packages/yaml/reader.py", line 87, in __init__
[006]     self.determine_encoding()
[006]   File "/usr/lib/python2.7/dist-packages/yaml/reader.py", line 126, in determine_encoding
[006]     self.update_raw()
[006]   File "/usr/lib/python2.7/dist-packages/yaml/reader.py", line 183, in update_raw
[006]     data = self.stream.read(size)
[006] AttributeError: 'NoneType' object has no attribute 'read'
[006] 
[006] 
[006] [Instance "election_replica1" returns with non-zero exit code: 1]
[006] 
[006] Last 15 lines of Tarantool Log file [Instance "election_replica1"][/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/election_replica1.log]:
[006] 2020-10-01 00:28:28.461 [29136] main/114/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock sio.c:193 !> SystemError connect to unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock, called on fd 22, aka unix/:(socket): No such file or directory
[006] 2020-10-01 00:28:28.461 [29136] main/114/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock I> will retry every 0.10 second
[006] 2020-10-01 00:28:28.461 [29136] main/112/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap1.sock I> remote master 242457fa-bfd4-4fcb-a63d-9ef429b7a2de at unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap1.sock running Tarantool 2.6.0
[006] 2020-10-01 00:28:28.661 [29136] main/113/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap2.sock I> remote master 0d895ae4-d579-4470-850a-fb36b55e9474 at unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap2.sock running Tarantool 2.6.0
[006] 2020-10-01 00:28:28.870 [29136] main/114/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock I> remote master 1a984638-93e7-4f31-9c78-5d4239260eb2 at unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock running Tarantool 2.6.0
[006] 2020-10-01 00:28:28.870 [29136] main/103/election_replica1 I> connected to 3 replicas
[006] 2020-10-01 00:28:28.870 [29136] main/103/election_replica1 I> bootstrapping replica from 1a984638-93e7-4f31-9c78-5d4239260eb2 at unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock
[006] 2020-10-01 00:28:28.870 [29136] main/114/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock I> can't read row
[006] 2020-10-01 00:28:28.870 [29136] main/114/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock box.cc:1945 E> ER_LOADING: Instance bootstrap hasn't finished yet
[006] 2020-10-01 00:28:28.870 [29136] main/114/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock I> will retry every 0.10 second
[006] 2020-10-01 00:28:28.975 [29136] main/114/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock I> can't read row
[006] 2020-10-01 00:28:28.975 [29136] main/114/applier/unix/:/builds/e94Uc7Js/0/tarantool/tarantool/test/var/006_replication/autobootstrap3.sock box.cc:178 E> ER_READONLY: Can't modify data because this instance is in read-only mode.
[006] 2020-10-01 00:28:28.975 [29136] main/103/election_replica1 box.cc:178 E> ER_READONLY: Can't modify data because this instance is in read-only mode.
[006] 2020-10-01 00:28:28.975 [29136] main/103/election_replica1 F> can't initialize storage: Can't modify data because this instance is in read-only mode.
[006] 2020-10-01 00:28:28.975 [29136] main/103/election_replica1 F> can't initialize storage: Can't modify data because this instance is in read-only mode.
[006] [ fail ]

Steps to reproduce:
Easy reproduced on FreeBSD VMware image:
Preparations:

diff --git a/test/replication/suite.ini b/test/replication/suite.ini
index 80e968d56..6f7470adf 100644
--- a/test/replication/suite.ini
+++ b/test/replication/suite.ini
@@ -11,7 +11,7 @@ use_unix_sockets_iproto = True
 long_run = prune.test.lua
 is_parallel = True
 pretest_clean = True
-fragile = {
+ALXfragile = {
     "retries": 10,
     "tests": {
         "errinj.test.lua": {

Run;

./test-run.py `for r in {1..10} ; do echo replication/election_basic.test.lua ; done` --long -j 10 --conf vinyl

Issue:

[001] replication/election_basic.test.lua             vinyl           [ fail ]
[001]
[001] Test failed! Result content mismatch:
[001] --- replication/election_basic.result     Tue Jun 15 12:18:01 2021
[003] replication/election_basic.test.lua             vinyl           [ pass ]
[001] +++ var/rejects/replication/election_basic.reject Tue Jun 15 14:15:10 2021
[001] @@ -153,7 +153,7 @@
[001]   | ...
[001]  assert(leader_count == 1)
[001]   | ---
[001] - | - true
[001] + | - error: assertion failed!
[001]   | ...
[001]  -- All nodes have the same leader.
[001]  r1_leader = test_run:eval('election_replica1', leader_id_cmd)[1]
[001] @@ -167,7 +167,7 @@
[001]   | ...
[001]  assert(r1_leader ~= 0)
[001]   | ---
[001] - | - true
[001] + | - error: assertion failed!
[001]   | ...
[001]  assert(r1_leader == r2_leader)
[001]   | ---
[001]

Also created smaller reproducer:

replication/alx2_election_basic.test.lua

test_run = require('test_run').new()
box.cfg{election_mode = 'candidate'}
test_run:wait_cond(function() return box.info.election.state == 'leader' end)
SERVERS = {'election_replica1', 'election_replica2', 'election_replica3'}
test_run:create_cluster(SERVERS, "replication")
test_run:wait_fullmesh(SERVERS)

leader_name = nil
is_leader_cmd = 'return box.info.election.state == \'leader\''
if test_run:eval('election_replica1', is_leader_cmd)[1] then                    \
    leader_name = 'election_replica1'                                           \
elseif test_run:eval('election_replica2', is_leader_cmd)[1] then                \
    leader_name = 'election_replica2'                                           \
elseif test_run:eval('election_replica3', is_leader_cmd)[1] then                \
    leader_name = 'election_replica3'                                           \
end
assert(leader_name ~= nil)
test_run:drop_cluster(SERVERS)

Initial run:

./test-run.py replication/alx2_election_basic.test.lua --update-result

Test run:

./test-run.py `for r in {1..10} ; do echo replication/alx2_election_basic.test.lua ; done` --long -j 10 --conf memtx

One of the failed result showed that leader set was not ready:

assert(leader_name ~= nil)
 | ---
 | - error: assertion failed!
 | ...

In real test the check is not correct:

leader_name = nil
..
if is_r1_leader then                                                            \
    leader_name = 'election_replica1'                                           \
..
elseif is_r2_leader then                                                        \
    leader_name = 'election_replica2'                                           \
..
else                                                                            \
    leader_name = 'election_replica3'                                           \
..
end

It means that leader if not ready sets to 'election_replica3'. It causes later fails in the test, like failing assert that checks that leader really exists. Before this block assert() fails on check that leader exists, it happened because of the same issue, check below that right after wait_fullmesh() call we think that leader would already exists, but in real it is not on too slow FreeBSD VMware image:

test_run:wait_fullmesh(SERVERS)
is_leader_cmd = 'return box.info.election.state == \'leader\''
leader_id_cmd = 'return box.info.election.leader'
is_r1_leader = test_run:eval('election_replica1', is_leader_cmd)[1]
is_r2_leader = test_run:eval('election_replica2', is_leader_cmd)[1]
is_r3_leader = test_run:eval('election_replica3', is_leader_cmd)[1]
leader_count = is_r1_leader and 1 or 0
leader_count = leader_count + (is_r2_leader and 1 or 0)
leader_count = leader_count + (is_r3_leader and 1 or 0)
assert(leader_count == 1)

Optional (but very desirable):

• coredump
• backtrace
• netstat

[Gerold103]

We need to make the leader waiting via test_run:wait_cond.