replication/sync.test.lua flaky fail in parallel mode

[sergw]

Tarantool version: 2.1 with branch: sergw/enable-parallel-test-replication-clean

OS version: docker-image:packpack/packpack:debian-stretch and ubuntu-cosmic

Bug description:

[002] replication/sync.test.lua                       memtx           [ fail ]
[002]
[002] Test failed! Result content mismatch:
[002] --- replication/sync.result	Fri Nov 23 12:10:21 2018
[002] +++ sync.reject	Mon Nov 26 10:13:38 2018
[002] @@ -97,7 +97,7 @@
[002]  ...
[002]  box.space.test:count()
[002]  ---
[002] -- 200
[002] +- 199
[002]  ...
[002]  box.info.status -- running
[002]  ---
[002]
[002] Last 15 lines of Tarantool Log file [Instance "master"][/tarantool/test/var/002_replication/master.log]:
[002] 2018-11-26 10:13:36.881 [91937] relay_0x55cfe54a2720/101/main I> recover from `/tarantool/test/var/002_replication/master/00000000000000000005.xlog'
[002] 2018-11-26 10:13:37.035 [91937] relay_0x55cfe54a2720/101/main I> done `/tarantool/test/var/002_replication/master/00000000000000000005.xlog'
[002] 2018-11-26 10:13:37.035 [91937] relay_0x55cfe54a2720/101/main I> recover from `/tarantool/test/var/002_replication/master/00000000000000000113.xlog'
[002] 2018-11-26 10:13:37.159 [91937] relay/127.0.0.1:57630/101/main C> exiting the relay loop
[002] 2018-11-26 10:13:37.207 [91937] relay_0x55cfe54a2720/101/main I> recover from `/tarantool/test/var/002_replication/master/00000000000000000113.xlog'
[002] 2018-11-26 10:13:37.389 [91937] relay_0x55cfe54a2720/101/main I> done `/tarantool/test/var/002_replication/master/00000000000000000113.xlog'
[002] 2018-11-26 10:13:37.389 [91937] relay_0x55cfe54a2720/101/main I> recover from `/tarantool/test/var/002_replication/master/00000000000000000313.xlog'
[002] 2018-11-26 10:13:37.516 [91937] relay/127.0.0.1:57676/101/main C> exiting the relay loop
[002] 2018-11-26 10:13:37.562 [91937] relay_0x55cfe54a2720/101/main I> recover from `/tarantool/test/var/002_replication/master/00000000000000000313.xlog'
[002] 2018-11-26 10:13:37.731 [91937] relay_0x55cfe54a2720/101/main I> done `/tarantool/test/var/002_replication/master/00000000000000000313.xlog'
[002] 2018-11-26 10:13:37.731 [91937] relay_0x55cfe54a2720/101/main I> recover from `/tarantool/test/var/002_replication/master/00000000000000000513.xlog'
[002] 2018-11-26 10:13:37.910 [91937] relay/127.0.0.1:57720/101/main C> exiting the relay loop
[002] 2018-11-26 10:13:38.020 [91937] relay_0x55cfe54a2720/101/main I> recover from `/tarantool/test/var/002_replication/master/00000000000000000513.xlog'
[002] 2018-11-26 10:13:38.021 [91937] relay_0x55cfe54a2720/101/main I> done `/tarantool/test/var/002_replication/master/00000000000000000513.xlog'
[002] 2018-11-26 10:13:38.112 [91937] relay/127.0.0.1:57790/101/main C> exiting the relay loop

Steps to reproduce:
root@b4840fa5ce95:/tarantool/test# python test-run.py $(for i in $(seq 1 52); do echo -n 'replication/sync.test.lua '; done)

reproduced only in parallel mode

[sergw]

Sometimes we have this issue:

[010] replication/sync.test.lua                       memtx           [ fail ]
[010] 
[010] Test failed! Result content mismatch:
[010] --- replication/sync.result  Thu Dec  6 23:05:48 2018
[010] +++ sync.reject  Thu Dec  6 23:12:16 2018
[010] @@ -300,8 +300,7 @@
[010]  ...
[010]  test_run:grep_log('replica', 'ER_CFG.*')
[010]  ---
[010] -- 'ER_CFG: Incorrect value for option ''replication'': duplicate connection with the
[010] -  same replica UUID'
[010] +- null
[010]  ...
[010]  test_run:cmd("switch default")
[010]  ---

Looks like it need to increase bytes in grep_log

[Totktonada]

Maybe replacing grep_log with wait_log will help with the latter error.

[sergw]

Maybe replacing grep_log with wait_log will help with the latter error.

Looks like it works

[sergw]

By using command: python test-run.py $(for i in $(seq 1 500); do echo -n " replication/sync.test.lua"; done) not always (sometimes):

[005] replication/sync.test.lua                       vinyl           [ fail ]
[005]
[005] Test failed! Result content mismatch:
[005] --- replication/sync.result	Tue Dec 11 07:43:20 2018
[005] +++ sync.reject	Tue Dec 11 08:36:34 2018
[005] @@ -288,15 +288,15 @@
[005]  ...
[005]  box.info.status -- running
[005]  ---
[005] -- running
[005] -...
[005] -box.info.ro -- false
[005] ----
[005] -- false
[005] +- orphan
[005] +...
[005] +box.info.ro -- false
[005] +---
[005] +- true
[005]  ...
[005]  box.info.replication[1].upstream.status -- follow
[005]  ---
[005] -- follow
[005] +- disconnected
[005]  ...
[005]  test_run:wait_log('replica', 'ER_CFG.*', nil, 1000)

[Totktonada]

Mostly fixed in def75c88fce61d27baf62aabfc7a8e5b4126c73a. So I'll drop sergw/fix-replication-sync-grep-log branch ( c69cf529fb5bbb87f49acac3fa69763b1482ed40 ).

However I observe the following miscompares when run the test in 16 threads (both memtx and vinyl confs):

[008] Test failed! Result content mismatch:
[008] --- replication/sync.result	Tue Apr 30 06:03:48 2019
[008] +++ replication/sync.reject	Sun May 12 17:46:39 2019
[008] @@ -214,7 +214,7 @@
[008]  -- Wait for remaining rows to arrive.
[008]  test_run:wait_cond(function() return box.space.test:count() == 600 end, 10)
[008]  ---
[008] -- true
[008] +- false
[008]  ...
[008]  -- Make sure replica leaves oprhan state.
[008]  test_run:wait_cond(function() return box.info.status ~= 'orphan' end, 10)

[avtikhon]

Checked the test and got the fails:

./test-run.py `for i in {1..52} ; do echo 'replication/sync.test.lua' ; done`

[001] --- replication/sync.result	Fri Jan 17 11:54:37 2020
[001] +++ replication/sync.reject	Mon Jan 20 11:54:40 2020
[001] @@ -109,15 +109,15 @@
[001]  ...
[001]  box.space.test:count()
[001]  ---
[001] -- 200
[001] -...
[001] -box.info.status -- running
[001] ----
[001] -- running
[001] -...
[001] -box.info.ro -- false
[001] ----
[001] -- false
[001] +- 0
[001] +...
[001] +box.info.status -- running
[001] +---
[001] +- orphan
[001] +...
[001] +box.info.ro -- false
[001] +---
[001] +- true
[001]  ...
[001]  -- Stop replication.
[001]  replication = box.cfg.replication
[001] @@ -156,11 +156,11 @@
[001]  ...
[001]  box.info.status -- running
[001]  ---
[001] -- running
[001] -...
[001] -box.info.ro -- false
[001] ----
[001] -- false
[001] +- orphan
[001] +...
[001] +box.info.ro -- false
[001] +---
[001] +- true
[001]  ...
[001]  -- Wait for remaining rows to arrive.

[001] --- replication/sync.result	Fri Jan 17 11:54:37 2020
[001] +++ replication/sync.reject	Mon Jan 20 12:00:53 2020
[001] @@ -109,15 +109,15 @@
[001]  ...
[001]  box.space.test:count()
[001]  ---
[001] -- 200
[001] -...
[001] -box.info.status -- running
[001] ----
[001] -- running
[001] -...
[001] -box.info.ro -- false
[001] ----
[001] -- false
[001] +- 0
[001] +...
[001] +box.info.status -- running
[001] +---
[001] +- orphan
[001] +...
[001] +box.info.ro -- false
[001] +---
[001] +- true
[001]  ...
[001]  -- Stop replication.
[001]  replication = box.cfg.replication
[001] @@ -156,16 +156,16 @@
[001]  ...
[001]  box.info.status -- running
[001]  ---
[001] -- running
[001] -...
[001] -box.info.ro -- false
[001] ----
[001] -- false
[001] +- orphan
[001] +...
[001] +box.info.ro -- false
[001] +---
[001] +- true
[001]  ...
[001]  -- Wait for remaining rows to arrive.
[001]  test_run:wait_cond(function() return box.space.test:count() == 400 end, 10)
[001]  ---
[001] -- true
[001] +- false
[001]  ...
[001]  -- Stop replication.
[001]  replication = box.cfg.replication
[001] @@ -213,7 +213,7 @@
[001]  -- Wait for remaining rows to arrive.
[001]  test_run:wait_cond(function() return box.space.test:count() == 600 end, 10)
[001]  ---
[001] -- true
[001] +- false
[001]  ...
[001]  -- Make sure replica leaves oprhan state.
[001]  test_run:wait_cond(function() return box.info.status ~= 'orphan' end, 10)
[001] @@ -337,11 +337,11 @@
[001]  ...
[001]  box.info.status -- running
[001]  ---
[001] -- running
[001] -...
[001] -box.info.ro -- false
[001] ----
[001] -- false
[001] +- orphan
[001] +...
[001] +box.info.ro -- false
[001] +---
[001] +- true
[001]  ...
[001]  test_run:cmd("switch default")
[001]  ---
[001]