test: flaky replication/election_qsync_stress.test.lua test

[avtikhon]

Tarantool version:
Tarantool 2.6.0-143-g0dc72812fb
Target: Linux-x86_64-Debug
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=ON
Compiler: /usr/bin/cc /usr/bin/c++
C_FLAGS: -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -fprofile-arcs -ftest-coverage -std=c11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-gnu-alignof-expression -fno-gnu89-inline -Wno-cast-function-type -Werror
CXX_FLAGS: -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -fprofile-arcs -ftest-coverage -std=c++11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type -Werror

OS version:

1. Linux (Debian 9)
2. FreeBSD 12

Bug description:
Found 2 issues:

1. https://gitlab.com/tarantool/tarantool/-/jobs/779113169#L5139

artifacts.zip

results file checksum: cc93d7c69c6368217634718bdf3de16c

[035] replication/election_qsync.test.lua             vinyl           
[035] TarantoolInpector.handle() received the following error:
[035] Traceback (most recent call last):
[035]   File "/builds/M4RrgQZ3/0/tarantool/tarantool/test-run/lib/inspector.py", line 94, in handle
[035]     result = self.parser.parse_preprocessor(line)
[035]   File "/builds/M4RrgQZ3/0/tarantool/tarantool/test-run/lib/preprocessor.py", line 73, in parse_preprocessor
[035]     return self.lua_eval(name, expr[1:-1])
[035]   File "/builds/M4RrgQZ3/0/tarantool/tarantool/test-run/lib/preprocessor.py", line 388, in lua_eval
[035]     self.servers[name].admin.reconnect()
[035] KeyError: 'election_replica0'
[035] [ fail ]
[035] 
[035] Test failed! Result content mismatch:
[035] --- replication/election_qsync.result	Thu Oct  8 00:07:13 2020
[035] +++ replication/election_qsync.reject	Thu Oct  8 04:11:02 2020
[035] @@ -102,27 +102,3 @@
[035]      old_leader_nr = new_leader_nr
[035]      old_leader = new_leader
[035]  end;
[035] - | ---
[035] - | ...
[035] -test_run:cmd('setopt delimiter ""');
[035] - | ---
[035] - | - true
[035] - | ...
[035] --- We're connected to some leader.
[035] -c.space.test:select{}
[035] - | ---
[035] - | - - [1]
[035] - |   - [2]
[035] - |   - [3]
[035] - |   - [4]
[035] - |   - [5]
[035] - |   - [6]
[035] - |   - [7]
[035] - |   - [8]
[035] - |   - [9]
[035] - |   - [10]
[035] - | ...
[035] -
[035] -test_run:drop_cluster(SERVERS)
[035] - | ---
[035] - | ...
[035] 

2. https://gitlab.com/tarantool/tarantool/-/jobs/779113714#L5729

artifacts.zip

results file checksum: 3fb2e6cef4c8fa1d0edd8654fd2d8ef6

[021] replication/election_qsync.test.lua             vinyl           
[021] TarantoolInpector.handle() received the following error:
[021] Traceback (most recent call last):
[021]   File "/home/vagrant/tarantool/test-run/lib/inspector.py", line 94, in handle
[021]     result = self.parser.parse_preprocessor(line)
[021]   File "/home/vagrant/tarantool/test-run/lib/preprocessor.py", line 106, in parse_preprocessor
[021]     return self.server(stype, sname, options)
[021]   File "/home/vagrant/tarantool/test-run/lib/preprocessor.py", line 338, in server
[021]     return getattr(self, attr)(ctype, sname, opts)
[021]   File "/home/vagrant/tarantool/test-run/lib/preprocessor.py", line 218, in server_stop
[021]     self.connections[sname].disconnect()
[021] KeyError: 'election_replica2'
[021] [ fail ]
[021] 
[021] Test failed! Result content mismatch:
[021] --- replication/election_qsync.result	Thu Oct  8 04:07:26 2020
[021] +++ replication/election_qsync.reject	Fri May  8 08:24:37 2020
[021] @@ -103,6 +103,7 @@
[021]      old_leader = new_leader
[021]  end;
[021]   | ---
[021] + | - error: Can't modify data because this instance is in read-only mode.
[021]   | ...
[021]  test_run:cmd('setopt delimiter ""');
[021]   | ---
[021] @@ -113,16 +114,6 @@
[021]   | ---
[021]   | - - [1]
[021]   |   - [2]
[021] - |   - [3]
[021] - |   - [4]
[021] - |   - [5]
[021] - |   - [6]
[021] - |   - [7]
[021] - |   - [8]
[021] - |   - [9]
[021] - |   - [10]
[021]   | ...
[021]  
[021]  test_run:drop_cluster(SERVERS)
[021] - | ---
[021] - | ...
[021] 

3. https://gitlab.com/tarantool/tarantool/-/jobs/795044495#L5273

artifacts.zip

results file checksum: 634bda94accdcdef7b1db3e14f28f445

[155] replication/election_qsync_stress.test.lua      memtx           
[155] TarantoolInpector.handle() received the following error:
[155] Traceback (most recent call last):
[155]   File "/builds/4BUsapPU/0/tarantool/tarantool/test-run/lib/inspector.py", line 94, in handle
[155]     result = self.parser.parse_preprocessor(line)
[155]   File "/builds/4BUsapPU/0/tarantool/tarantool/test-run/lib/preprocessor.py", line 106, in parse_preprocessor
[155]     return self.server(stype, sname, options)
[155]   File "/builds/4BUsapPU/0/tarantool/tarantool/test-run/lib/preprocessor.py", line 338, in server
[155]     return getattr(self, attr)(ctype, sname, opts)
[155]   File "/builds/4BUsapPU/0/tarantool/tarantool/test-run/lib/preprocessor.py", line 218, in server_stop
[155]     self.connections[sname].disconnect()
[155] KeyError: 'election_replica3'
[155] [ fail ]
[155] 
[155] Test failed! Result content mismatch:
[155] --- replication/election_qsync_stress.result	Fri Oct 16 11:31:28 2020
[155] +++ replication/election_qsync_stress.reject	Fri Oct 16 12:12:35 2020
[155] @@ -102,6 +102,7 @@
[155]      old_leader = new_leader
[155]  end;
[155]   | ---
[155] + | - error: Can't modify data because this instance is in read-only mode.
[155]   | ...
[155]  test_run:cmd('setopt delimiter ""');
[155]   | ---
[155] @@ -110,9 +111,7 @@
[155]  -- We're connected to some leader.
[155]  #c.space.test:select{} == 10 or require('log').error(c.space.test:select{})
[155]   | ---
[155] - | - true
[155] + | - null
[155]   | ...
[155]  
[155]  test_run:drop_cluster(SERVERS)
[155] - | ---
[155] - | ...
[155] 

https://gitlab.com/tarantool/tarantool/-/jobs/795376806#L5359

artifacts.zip

results file checksum: 36bcdae426c18a60fd13025c09f197d0

[164] --- replication/election_qsync_stress.result	Fri Oct 16 14:39:00 2020
[164] +++ replication/election_qsync_stress.reject	Fri Oct 16 14:48:14 2020
[164] @@ -110,7 +110,7 @@
[164]  -- We're connected to some leader.
[164]  #c.space.test:select{} == 10 or require('log').error(c.space.test:select{})
[164]   | ---
[164] - | - true
[164] + | - null
[164]   | ...
[164]  
[164]  test_run:drop_cluster(SERVERS)
[164] 

https://gitlab.com/tarantool/tarantool/-/jobs/795916093#L5738

artifacts.zip

results file checksum: 209c865525154a91435c63850f15eca0

[027] --- replication/election_qsync_stress.result	Fri Oct 16 19:25:53 2020
[027] +++ replication/election_qsync_stress.reject	Fri May  8 08:23:59 2020
[027] @@ -102,6 +102,7 @@
[027]      old_leader = new_leader
[027]  end;
[027]   | ---
[027] + | - error: Found uncommitted sync transactions from other instance with id 2
[027]   | ...
[027]  test_run:cmd('setopt delimiter ""');
[027]   | ---
[027] @@ -110,9 +111,7 @@
[027]  -- We're connected to some leader.
[027]  #c.space.test:select{} == 10 or require('log').error(c.space.test:select{})
[027]   | ---
[027] - | - true
[027] + | - null
[027]   | ...
[027]  
[027]  test_run:drop_cluster(SERVERS)
[027] - | ---
[027] - | ...
[027] 

Steps to reproduce:

Optional (but very desirable):

• coredump
• backtrace
• netstat

[PersDep]

It also catches assertion time to time:

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
tarantool/tarantool#1  0x00007f0cf07da8b1 in __GI_abort () at abort.c:79
tarantool/tarantool#2  0x00007f0cf07ca42a in __assert_fail_base (fmt=0x7f0cf0951a38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55e86001da89 "lsn > limbo->confirmed_lsn", 
    file=file@entry=0x55e86001d708 "/home/kosarev/tarantool/src/box/txn_limbo.c", line=line@entry=340, function=function@entry=0x55e86001dc40 <__PRETTY_FUNCTION__.12489> "txn_limbo_write_confirm")
    at assert.c:92
tarantool/tarantool#3  0x00007f0cf07ca4a2 in __GI___assert_fail (assertion=0x55e86001da89 "lsn > limbo->confirmed_lsn", file=0x55e86001d708 "/home/kosarev/tarantool/src/box/txn_limbo.c", line=340, 
    function=0x55e86001dc40 <__PRETTY_FUNCTION__.12489> "txn_limbo_write_confirm") at assert.c:101
tarantool/tarantool#4  0x000055e85fbdb753 in txn_limbo_write_confirm (limbo=0x55e860416a60 <txn_limbo>, lsn=9) at /home/kosarev/tarantool/src/box/txn_limbo.c:340
tarantool/tarantool#5  0x000055e85fbdc328 in txn_limbo_force_empty (limbo=0x55e860416a60 <txn_limbo>, confirm_lsn=9) at /home/kosarev/tarantool/src/box/txn_limbo.c:622
tarantool/tarantool#6  0x000055e85fbe291e in box_clear_synchro_queue () at /home/kosarev/tarantool/src/box/box.cc:1071
tarantool/tarantool#7  0x000055e85fcb5cd3 in lbox_ctl_clear_synchro_queue (L=0x4151c0b8) at /home/kosarev/tarantool/src/box/lua/ctl.c:85
tarantool/tarantool#8  0x000055e85fe400cb in lj_BC_FUNCC ()
tarantool/tarantool#9  0x000055e85fdfb84b in jit_secure_call (L=0x4151c0b8, base=0x4151c118, nres=0) at lj_api.c:88
tarantool/tarantool#10 0x000055e85fe02ae0 in lua_call (L=0x4151c0b8, nargs=0, nresults=-1) at lj_api.c:1133
tarantool/tarantool#11 0x000055e85fca3b94 in execute_lua_eval (L=0x4151c0b8) at /home/kosarev/tarantool/src/box/lua/call.c:394
tarantool/tarantool#12 0x000055e85fe400cb in lj_BC_FUNCC ()
tarantool/tarantool#13 0x000055e85fe02e15 in lua_pcall (L=0x4151c0b8, nargs=1, nresults=-1, errfunc=0) at lj_api.c:1158
tarantool/tarantool#14 0x000055e85fd87bd6 in luaT_call (L=0x4151c0b8, nargs=1, nreturns=-1) at /home/kosarev/tarantool/src/lua/utils.c:1016
tarantool/tarantool#15 0x000055e85fca42e1 in box_process_lua (handler=HANDLER_EVAL, ctx=0x7f0ce79ffd10, ret=0x7f0ce79ffe60) at /home/kosarev/tarantool/src/box/lua/call.c:570
tarantool/tarantool#16 0x000055e85fca43ff in box_lua_eval (expr=0x7f0ce701803d "box.ctl.clear_synchro_queue()!\220\021", expr_len=29, args=0x7f0ce79ffd80, ret=0x7f0ce79ffe60)
    at /home/kosarev/tarantool/src/box/lua/call.c:614
tarantool/tarantool#17 0x000055e85fc130bb in box_process_eval (request=0x7f0ce7010430, port=0x7f0ce79ffe60) at /home/kosarev/tarantool/src/box/call.c:187
tarantool/tarantool#18 0x000055e85fcc75f4 in tx_process_call (m=0x7f0ce70103b0) at /home/kosarev/tarantool/src/box/iproto.cc:1632
tarantool/tarantool#19 0x000055e85fdb062e in cmsg_deliver (msg=0x7f0ce70103b0) at /home/kosarev/tarantool/src/lib/core/cbus.c:375
tarantool/tarantool#20 0x000055e85fdb170a in fiber_pool_f (ap=0x7f0ced801008) at /home/kosarev/tarantool/src/lib/core/fiber_pool.c:64
tarantool/tarantool#21 0x000055e85fba0269 in fiber_cxx_invoke(fiber_func, typedef __va_list_tag __va_list_tag *) (f=0x55e85fdb156a <fiber_pool_f>, ap=0x7f0ced801008) at /home/kosarev/tarantool/src/lib/core/fiber.h:788
tarantool/tarantool#22 0x000055e85fdaae15 in fiber_loop (data=0x0) at /home/kosarev/tarantool/src/lib/core/fiber.c:879
tarantool/tarantool#23 0x000055e86001556d in coro_init () at /home/kosarev/tarantool/third_party/coro/coro.c:110

[Gerold103]

A minimal 100% reproducer. Follow the steps in the specified order on the specified instances.
However it is not related to why the test hangs sometimes. This I don't know.

-- Instance 1
-- Step 1
fiber = require('fiber')
box.cfg{
    listen = 3313,
    replication = {'localhost:3313', 'localhost:3314'},
    replication_synchro_quorum = 2,
    replication_synchro_timeout = 1000000,
    read_only = false,
}
box.schema.user.grant('guest', 'super')
s1 = box.schema.create_space('test1', {is_sync = true})
_ = s1:create_index('pk')

-- Step 3
for i = 1, 10 do s1:replace{i} end

-- Step 5
box.cfg{
    replication_synchro_timeout = 0.001,
}
box.ctl.clear_synchro_queue()

-- Instance 2
-- Step 2
box.cfg{
    listen = 3314,
    replication = {'localhost:3313', 'localhost:3314'},
    replication_synchro_quorum = 3,
    replication_synchro_timeout = 1000000,
    read_only = true,
}

-- Step 4
box.cfg{read_only = false}
box.space.test1:replace{11}