From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtpng2.m.smailru.net (smtpng2.m.smailru.net [94.100.179.3]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dev.tarantool.org (Postfix) with ESMTPS id 7723F4696C8 for ; Tue, 26 Nov 2019 09:22:03 +0300 (MSK) From: "Alexander V. Tikhonov" Date: Tue, 26 Nov 2019 09:21:47 +0300 Message-Id: In-Reply-To: <1c42ad20160f47d942cab405ce9896d6d31cc05f.1574749278.git.avtikhon@tarantool.org> References: <1c42ad20160f47d942cab405ce9896d6d31cc05f.1574749278.git.avtikhon@tarantool.org> In-Reply-To: <1c42ad20160f47d942cab405ce9896d6d31cc05f.1574749278.git.avtikhon@tarantool.org> References: <1c42ad20160f47d942cab405ce9896d6d31cc05f.1574749278.git.avtikhon@tarantool.org> Subject: [Tarantool-patches] [PATCH v1 11/12] test: fix replication/gc flaky failures List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Kirill Yukhin Cc: tarantool-patches@dev.tarantool.org From: avtikhon Two problems are fixed here. The first one is about correctness of the test case. The second is about flaky failures. About correctness. The test case contains the following lines: | test_run:cmd("switch replica") | -- Unblock the replica and break replication. | box.error.injection.set("ERRINJ_WAL_DELAY", false) | box.cfg{replication = {}} Usually rows are applied and the new vclock is sent to the master before replication will be disabled. So the master removes old xlog before the replica restart and the next case tests nothing. This commit uses the new test-run's ability to stop a tarantool instance with a custom signal and stops the replica with SIGKILL w/o dropping ERRINJ_WAL_DELAY. This change fixes the race between applying rows and disabling replication and so makes the test case correct. About flaky failures. They were look like so: | [029] --- replication/gc.result Mon Apr 15 14:58:09 2019 | [029] +++ replication/gc.reject Tue Apr 16 09:17:47 2019 | [029] @@ -290,7 +290,12 @@ | [029] ... | [029] wait_xlog(1) or fio.listdir('./master') | [029] --- | [029] -- true | [029] +- - 00000000000000000305.vylog | [029] + - 00000000000000000305.xlog | [029] + - '512' | [029] + - 00000000000000000310.xlog | [029] + - 00000000000000000310.vylog | [029] + - 00000000000000000310.snap | [029] ... | [029] -- Stop the replica. | [029] test_run:cmd("stop server replica") | <...next cases could have induced mismathes too...> The reason of the fail is that a replica applied all rows from the old xlog, but didn't sent an ACK with a new vclock to a master, because the replication was disabled before that. The master stops relay and keeps the old xlog. When the replica starts again it subscribes with the vclock value that instructs a relay to open the new xlog. Tarantool can remove an old xlog just after a replica's ACK when observes that the xlog was fully read by all replicas. But tarantool does not remove xlogs when a replica is subscribed. This is not a big problem, because such 'stuck' xlog file will be removed with a next xlog removal. There was the attempt to fix this behaviour and remove old xlogs at subscribe, see the following commits: * b5b4809cf2e6d48230eb9e4301eac188b080e0f4 ('replication: update replica gc state on subscribe'); * 766cd3e1015f6f76460a748c37212fb4c8791500 ('Revert "replication: update replica gc state on subscribe"'). Anyway, this commit fixes this flaky failures, because stops the replica before applying rows from the old xlog. So when the replica starts it continues reading from the old xlog and the xlog file will be removed when will be fully read. Closes #4162 (cherry picked from commit 35b5095ab0f437df6e78b1bacf4d41c3737a540e) --- test/replication/gc.result | 16 +++++++--------- test/replication/gc.test.lua | 16 ++++++++-------- 2 files changed, 15 insertions(+), 17 deletions(-) diff --git a/test/replication/gc.result b/test/replication/gc.result index cbdeffb11..5d55403b0 100644 --- a/test/replication/gc.result +++ b/test/replication/gc.result @@ -236,20 +236,18 @@ fiber.sleep(0.1) -- wait for master to relay data --- - true ... -test_run:cmd("switch replica") +-- Imitate the replica crash and, then, wake up. +-- Just 'stop server replica' (SIGTERM) is not sufficient to stop +-- a tarantool instance when ERRINJ_WAL_DELAY is set, because +-- "tarantool" thread wait for paused "wal" thread infinitely. +test_run:cmd("stop server replica with signal=KILL") --- - true ... --- Unblock the replica and break replication. -box.error.injection.set("ERRINJ_WAL_DELAY", false) ---- -- ok -... -box.cfg{replication = {}} +test_run:cmd("start server replica") --- +- true ... --- Restart the replica to reestablish replication. -test_run:cmd("restart server replica") -- Wait for the replica to catch up. test_run:cmd("switch replica") --- diff --git a/test/replication/gc.test.lua b/test/replication/gc.test.lua index 4710fd9e3..40a349167 100644 --- a/test/replication/gc.test.lua +++ b/test/replication/gc.test.lua @@ -110,14 +110,14 @@ fiber.sleep(0.1) -- wait for master to relay data -- Garbage collection must not delete the old xlog file -- because it is still needed by the replica, but remove -- the old snapshot. -#box.info.gc().checkpoints == 1 or box.info.gc() -#fio.glob('./master/*.xlog') == 2 or fio.listdir('./master') -test_run:cmd("switch replica") --- Unblock the replica and break replication. -box.error.injection.set("ERRINJ_WAL_DELAY", false) -box.cfg{replication = {}} --- Restart the replica to reestablish replication. -test_run:cmd("restart server replica") +wait_gc(1) or box.info.gc() +wait_xlog(2) or fio.listdir('./master') +-- Imitate the replica crash and, then, wake up. +-- Just 'stop server replica' (SIGTERM) is not sufficient to stop +-- a tarantool instance when ERRINJ_WAL_DELAY is set, because +-- "tarantool" thread wait for paused "wal" thread infinitely. +test_run:cmd("stop server replica with signal=KILL") +test_run:cmd("start server replica") -- Wait for the replica to catch up. test_run:cmd("switch replica") test_run:wait_cond(function() return box.space.test:count() == 310 end, 10) -- 2.17.1