[PATCH 1/2] test: fix vinyl/errinj_stat again

[PATCH 1/2] test: fix vinyl/errinj_stat again

[Vladimir Davydov]

Another failure this time:

 | [024] —- vinyl/errinj_stat.result  Wed Apr 10 14:21:34 2019
 | [024] +++ vinyl/errinj_stat.reject  Wed Apr 10 14:24:15 2019
 | [024] @@ -220,7 +220,7 @@
 | [024]  ...
 | [024]  box.snapshot()
 | [024]  —-
 | [024] — error: Error injection 'vinyl dump'
 | [024] +- error: Snapshot is already in progress
 | [024]  ...
 | [024]  stat = box.stat.vinyl().scheduler
 | [024]  —-
 | [024] @@ -231,7 +231,7 @@
 | [024]  ...
 | [024]  stat.tasks_failed > 0
 | [024]  —-
 | [024] — true
 | [024] +- false
 | [024]  ...
 | [024]  errinj.set('ERRINJ_VY_RUN_WRITE', false)
 | [024]  —-

Hope it's the last time we fix it.

Follow-up commit f4b80bcf4908 ("test: fix vinyl/errinj_stat failure").
---
 test/vinyl/errinj_stat.result   | 8 ++++++++
 test/vinyl/errinj_stat.test.lua | 2 ++
 2 files changed, 10 insertions(+)

diff --git a/test/vinyl/errinj_stat.result b/test/vinyl/errinj_stat.result
index a4e63357..f1133137 100644
--- a/test/vinyl/errinj_stat.result
+++ b/test/vinyl/errinj_stat.result
@@ -191,6 +191,10 @@ test_run:wait_cond(function() return box.stat.vinyl().scheduler.tasks_completed
 ---
 - true
 ...
+test_run:wait_cond(function() return not box.info.gc().checkpoint_is_in_progress end)
+---
+- true
+...
 stat = box.stat.vinyl().scheduler
 ---
 ...
@@ -325,6 +329,10 @@ test_run:wait_cond(function() return box.stat.vinyl().scheduler.tasks_completed
 ---
 - true
 ...
+test_run:wait_cond(function() return not box.info.gc().checkpoint_is_in_progress end)
+---
+- true
+...
 i:stat().disk.dump.time >= 0.1
 ---
 - true
diff --git a/test/vinyl/errinj_stat.test.lua b/test/vinyl/errinj_stat.test.lua
index c3000bba..d11da450 100644
--- a/test/vinyl/errinj_stat.test.lua
+++ b/test/vinyl/errinj_stat.test.lua
@@ -60,6 +60,7 @@ box.stat.reset() -- doesn't affect tasks_inprogress
 box.stat.vinyl().scheduler.tasks_inprogress > 0
 errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', false)
 test_run:wait_cond(function() return box.stat.vinyl().scheduler.tasks_completed > 0 end)
+test_run:wait_cond(function() return not box.info.gc().checkpoint_is_in_progress end)
 stat = box.stat.vinyl().scheduler
 stat.tasks_inprogress == 0
 stat.tasks_completed == 1
@@ -101,6 +102,7 @@ test_run:wait_cond(function() return box.stat.vinyl().scheduler.tasks_inprogress
 fiber.sleep(0.1)
 errinj.set('ERRINJ_VY_RUN_WRITE_DELAY', false)
 test_run:wait_cond(function() return box.stat.vinyl().scheduler.tasks_completed > 0 end)
+test_run:wait_cond(function() return not box.info.gc().checkpoint_is_in_progress end)
 i:stat().disk.dump.time >= 0.1
 i:stat().disk.dump.time <= fiber.time() - start_time
 i:stat().disk.compaction.time == 0
-- 
2.11.0

[PATCH 2/2] test: fix vinyl/errinj_ddl failure

[Vladimir Davydov]

The test fixes the following two test failures:

 | --- vinyl/errinj_ddl.result	Tue Mar 19 17:52:48 2019
 | +++ vinyl/errinj_ddl.reject	Tue Mar 19 19:05:36 2019
 | @@ -358,7 +358,7 @@
 | ...
 | s.index.sk:stat().memory.rows
 | ---
 | -- 27
 | +- 23
 | ...
 | test_run:cmd('restart server default')
 | fiber = require('fiber')

This happens, because creation of the test index can happen later than
we expect. Fix it by adding an appropriate wait_cond.

 | --- vinyl/errinj_ddl.result	Tue Mar 19 17:52:48 2019
 | +++ vinyl/errinj_ddl.reject	Tue Mar 19 18:07:55 2019
 | @@ -504,6 +504,7 @@
 | ...
 | _ = s1:create_index('sk', {parts = {2, 'unsigned'}})
 | ---
 | +- error: Tuple field 2 required by space format is missing
 | ...
 | errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", 0)
 | ---

This one is due to a test transaction completing before DDL starts so
that the transaction isn't aborted by DDL, as we expect. Fix it by
making sure the transaction won't commit before DDL starts, again with
the aid of wait_cond.

 | --- vinyl/errinj_ddl.result     Wed Apr 10 18:59:57 2019
 | +++ vinyl/errinj_ddl.reject     Wed Apr 10 19:05:35 2019
 | @@ -779,7 +779,7 @@
 |  ...
 |  ch1:get()
 |  ---
 | -- Transaction has been aborted by conflict
 | +- Duplicate key exists in unique index 'i1' in space 'test'
 |  ...
 |  ch2:get()
 |  ---

This test case fails, because we use a timeout to stall reading DML
operations. This was initially a bad call, because under severe load
(e.g. parallel test run), the timeout may fire before we get to execute
the DDL request, which is supposed to abort the DML operations, in which
case they won't be aborted. Fix this by replacing the timeout with a
delay, as we should have done right from the start.

Closes #4056
Closes #4057
---
 src/box/vy_run.c               |  6 +++++
 src/lib/core/errinj.h          |  1 +
 test/box/errinj.result         | 50 ++++++++++++++++++++++--------------------
 test/vinyl/errinj_ddl.result   | 37 +++++++++++++++++++++----------
 test/vinyl/errinj_ddl.test.lua | 29 ++++++++++++++----------
 5 files changed, 76 insertions(+), 47 deletions(-)

diff --git a/src/box/vy_run.c b/src/box/vy_run.c
index 03db2f50..de4d67ac 100644
--- a/src/box/vy_run.c
+++ b/src/box/vy_run.c
@@ -835,6 +835,12 @@ vy_page_read(struct vy_page *page, const struct vy_page_info *page_info,
 	if (inj != NULL && inj->dparam > 0)
 		usleep(inj->dparam * 1000000);
 
+	inj = errinj(ERRINJ_VY_READ_PAGE_DELAY, ERRINJ_BOOL);
+	if (inj != NULL) {
+		while (inj->bparam)
+			usleep(10000);
+	}
+
 	/* decode xlog tx */
 	const char *data_pos = data;
 	const char *data_end = data + readen;
diff --git a/src/lib/core/errinj.h b/src/lib/core/errinj.h
index 6663b17c..5d9317d5 100644
--- a/src/lib/core/errinj.h
+++ b/src/lib/core/errinj.h
@@ -89,6 +89,7 @@ struct errinj {
 	_(ERRINJ_VY_INDEX_DUMP, ERRINJ_INT, {.iparam = -1}) \
 	_(ERRINJ_VY_TASK_COMPLETE, ERRINJ_BOOL, {.bparam = false}) \
 	_(ERRINJ_VY_READ_PAGE, ERRINJ_BOOL, {.bparam = false}) \
+	_(ERRINJ_VY_READ_PAGE_DELAY, ERRINJ_BOOL, {.bparam = false}) \
 	_(ERRINJ_VY_READ_PAGE_TIMEOUT, ERRINJ_DOUBLE, {.dparam = 0}) \
 	_(ERRINJ_VY_SQUASH_TIMEOUT, ERRINJ_DOUBLE, {.dparam = 0}) \
 	_(ERRINJ_VY_SCHED_TIMEOUT, ERRINJ_DOUBLE, {.dparam = 0}) \
diff --git a/test/box/errinj.result b/test/box/errinj.result
index af95134a..68b137a1 100644
--- a/test/box/errinj.result
+++ b/test/box/errinj.result
@@ -38,21 +38,23 @@ errinj.info()
     state: false
   ERRINJ_VYRUN_INDEX_GARBAGE:
     state: false
+  ERRINJ_VY_INDEX_FILE_RENAME:
+    state: false
   ERRINJ_VY_DELAY_PK_LOOKUP:
     state: false
   ERRINJ_VY_TASK_COMPLETE:
     state: false
   ERRINJ_PORT_DUMP:
     state: false
-  ERRINJ_RELAY_BREAK_LSN:
-    state: -1
+  ERRINJ_VY_POINT_ITER_WAIT:
+    state: false
   ERRINJ_WAL_IO:
     state: false
   ERRINJ_WAL_FALLOCATE:
     state: 0
-  ERRINJ_RELAY_EXIT_DELAY:
-    state: 0
-  ERRINJ_SNAP_COMMIT_DELAY:
+  ERRINJ_WAL_BREAK_LSN:
+    state: -1
+  ERRINJ_LOG_ROTATE:
     state: false
   ERRINJ_TUPLE_FORMAT_COUNT:
     state: -1
@@ -64,7 +66,7 @@ errinj.info()
     state: false
   ERRINJ_RELAY_REPORT_INTERVAL:
     state: 0
-  ERRINJ_WAL_BREAK_LSN:
+  ERRINJ_RELAY_BREAK_LSN:
     state: -1
   ERRINJ_VY_READ_PAGE_TIMEOUT:
     state: 0
@@ -72,18 +74,18 @@ errinj.info()
     state: false
   ERRINJ_SIO_READ_MAX:
     state: -1
-  ERRINJ_VY_INDEX_FILE_RENAME:
-    state: false
-  ERRINJ_WAL_WRITE_DISK:
-    state: false
   ERRINJ_VY_RUN_FILE_RENAME:
     state: false
+  ERRINJ_WAL_WRITE_DISK:
+    state: false
   ERRINJ_VY_LOG_FILE_RENAME:
     state: false
-  ERRINJ_VY_RUN_WRITE:
-    state: false
   ERRINJ_HTTP_RESPONSE_ADD_WAIT:
     state: false
+  ERRINJ_VY_RUN_WRITE:
+    state: false
+  ERRINJ_SNAP_COMMIT_DELAY:
+    state: false
   ERRINJ_VY_LOG_FLUSH_DELAY:
     state: false
   ERRINJ_RELAY_FINAL_JOIN:
@@ -96,34 +98,34 @@ errinj.info()
     state: false
   ERRINJ_WAL_ROTATE:
     state: false
-  ERRINJ_LOG_ROTATE:
-    state: false
-  ERRINJ_VY_POINT_ITER_WAIT:
-    state: false
+  ERRINJ_BUILD_INDEX:
+    state: -1
+  ERRINJ_RELAY_EXIT_DELAY:
+    state: 0
   ERRINJ_MEMTX_DELAY_GC:
     state: false
   ERRINJ_IPROTO_TX_DELAY:
     state: false
-  ERRINJ_BUILD_INDEX:
-    state: -1
   ERRINJ_XLOG_READ:
     state: -1
-  ERRINJ_XLOG_GARBAGE:
-    state: false
   ERRINJ_TUPLE_FIELD:
     state: false
+  ERRINJ_XLOG_GARBAGE:
+    state: false
   ERRINJ_INDEX_ALLOC:
     state: false
+  ERRINJ_VY_READ_PAGE_DELAY:
+    state: false
   ERRINJ_TESTING:
     state: false
-  ERRINJ_RELAY_SEND_DELAY:
-    state: false
+  ERRINJ_RELAY_TIMEOUT:
+    state: 0
   ERRINJ_VY_SQUASH_TIMEOUT:
     state: 0
   ERRINJ_VY_LOG_FLUSH:
     state: false
-  ERRINJ_RELAY_TIMEOUT:
-    state: 0
+  ERRINJ_RELAY_SEND_DELAY:
+    state: false
 ...
 errinj.set("some-injection", true)
 ---
diff --git a/test/vinyl/errinj_ddl.result b/test/vinyl/errinj_ddl.result
index 794125e8..af5f73d4 100644
--- a/test/vinyl/errinj_ddl.result
+++ b/test/vinyl/errinj_ddl.result
@@ -287,8 +287,9 @@ ch = fiber.channel(1)
 _ = fiber.create(function() s:create_index('sk', {parts = {2, 'integer'}}) ch:put(true) end)
 ---
 ...
-fiber.sleep(0.01)
+test_run:wait_cond(function() return box.stat.vinyl().scheduler.tasks_inprogress > 0 end)
 ---
+- true
 ...
 _ = s:delete{1}
 ---
@@ -412,13 +413,13 @@ box.cfg{vinyl_cache = 0}
 s1 = box.schema.space.create('test1', {engine = 'vinyl'})
 ---
 ...
-_ = s1:create_index('pk', {page_size = 16})
+i1 = s1:create_index('pk', {page_size = 16})
 ---
 ...
 s2 = box.schema.space.create('test2', {engine = 'vinyl'})
 ---
 ...
-_ = s2:create_index('pk')
+i2 = s2:create_index('pk')
 ---
 ...
 pad = string.rep('x', 16)
@@ -435,12 +436,12 @@ test_run:cmd("setopt delimiter ';'")
 ---
 - true
 ...
-function async_replace(space, tuple, timeout)
+function async_replace(space, tuple, wait_cond)
     local c = fiber.channel(1)
     fiber.create(function()
         box.begin()
         space:replace(tuple)
-        fiber.sleep(timeout)
+        test_run:wait_cond(wait_cond)
         local status = pcall(box.commit)
         c:put(status)
     end)
@@ -452,10 +453,17 @@ test_run:cmd("setopt delimiter ''");
 ---
 - true
 ...
-c1 = async_replace(s1, {1}, 0.01)
+-- Wait until DDL starts scanning the altered space.
+lookup = i1:stat().lookup
 ---
 ...
-c2 = async_replace(s2, {1}, 0.01)
+wait_cond = function() return i1:stat().lookup > lookup end
+---
+...
+c1 = async_replace(s1, {1}, wait_cond)
+---
+...
+c2 = async_replace(s2, {1}, wait_cond)
 ---
 ...
 errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", 0.001)
@@ -492,10 +500,17 @@ s1:format()
 s1:format{}
 ---
 ...
-c1 = async_replace(s1, {2}, 0.01)
+-- Wait until DDL starts scanning the altered space.
+lookup = i1:stat().lookup
 ---
 ...
-c2 = async_replace(s2, {2}, 0.01)
+wait_cond = function() return i1:stat().lookup > lookup end
+---
+...
+c1 = async_replace(s1, {2}, wait_cond)
+---
+...
+c2 = async_replace(s2, {2}, wait_cond)
 ---
 ...
 errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", 0.001)
@@ -737,7 +752,7 @@ test_run:cmd("setopt delimiter ''");
 ...
 -- Issue a few DML requests that require reading disk.
 -- Stall disk reads.
-errinj.set('ERRINJ_VY_READ_PAGE_TIMEOUT', 0.01)
+errinj.set('ERRINJ_VY_READ_PAGE_DELAY', true)
 ---
 - ok
 ...
@@ -758,7 +773,7 @@ s.index.i4:drop()
 ---
 ...
 -- Resume the DML requests. Check that they have been aborted.
-errinj.set('ERRINJ_VY_READ_PAGE_TIMEOUT', 0)
+errinj.set('ERRINJ_VY_READ_PAGE_DELAY', false)
 ---
 - ok
 ...
diff --git a/test/vinyl/errinj_ddl.test.lua b/test/vinyl/errinj_ddl.test.lua
index 84f33277..57af9c65 100644
--- a/test/vinyl/errinj_ddl.test.lua
+++ b/test/vinyl/errinj_ddl.test.lua
@@ -130,8 +130,7 @@ for i = 1, 5 do s:replace{i, i} end
 errinj.set("ERRINJ_VY_RUN_WRITE_DELAY", true)
 ch = fiber.channel(1)
 _ = fiber.create(function() s:create_index('sk', {parts = {2, 'integer'}}) ch:put(true) end)
-
-fiber.sleep(0.01)
+test_run:wait_cond(function() return box.stat.vinyl().scheduler.tasks_inprogress > 0 end)
 
 _ = s:delete{1}
 _ = s:replace{2, -2}
@@ -182,21 +181,21 @@ vinyl_cache = box.cfg.vinyl_cache
 box.cfg{vinyl_cache = 0}
 
 s1 = box.schema.space.create('test1', {engine = 'vinyl'})
-_ = s1:create_index('pk', {page_size = 16})
+i1 = s1:create_index('pk', {page_size = 16})
 s2 = box.schema.space.create('test2', {engine = 'vinyl'})
-_ = s2:create_index('pk')
+i2 = s2:create_index('pk')
 
 pad = string.rep('x', 16)
 for i = 101, 200 do s1:replace{i, i, pad} end
 box.snapshot()
 
 test_run:cmd("setopt delimiter ';'")
-function async_replace(space, tuple, timeout)
+function async_replace(space, tuple, wait_cond)
     local c = fiber.channel(1)
     fiber.create(function()
         box.begin()
         space:replace(tuple)
-        fiber.sleep(timeout)
+        test_run:wait_cond(wait_cond)
         local status = pcall(box.commit)
         c:put(status)
     end)
@@ -204,8 +203,11 @@ function async_replace(space, tuple, timeout)
 end;
 test_run:cmd("setopt delimiter ''");
 
-c1 = async_replace(s1, {1}, 0.01)
-c2 = async_replace(s2, {1}, 0.01)
+-- Wait until DDL starts scanning the altered space.
+lookup = i1:stat().lookup
+wait_cond = function() return i1:stat().lookup > lookup end
+c1 = async_replace(s1, {1}, wait_cond)
+c2 = async_replace(s2, {1}, wait_cond)
 
 errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", 0.001)
 s1:format{{'key', 'unsigned'}, {'value', 'unsigned'}}
@@ -219,8 +221,11 @@ s2:get(1) ~= nil
 s1:format()
 s1:format{}
 
-c1 = async_replace(s1, {2}, 0.01)
-c2 = async_replace(s2, {2}, 0.01)
+-- Wait until DDL starts scanning the altered space.
+lookup = i1:stat().lookup
+wait_cond = function() return i1:stat().lookup > lookup end
+c1 = async_replace(s1, {2}, wait_cond)
+c2 = async_replace(s2, {2}, wait_cond)
 
 errinj.set("ERRINJ_VY_READ_PAGE_TIMEOUT", 0.001)
 _ = s1:create_index('sk', {parts = {2, 'unsigned'}})
@@ -329,7 +334,7 @@ test_run:cmd("setopt delimiter ''");
 
 -- Issue a few DML requests that require reading disk.
 -- Stall disk reads.
-errinj.set('ERRINJ_VY_READ_PAGE_TIMEOUT', 0.01)
+errinj.set('ERRINJ_VY_READ_PAGE_DELAY', true)
 
 ch1 = async(function() s:insert({1, 1, 1, 1}) end)
 ch2 = async(function() s:replace({2, 3, 2, 3}) end)
@@ -340,7 +345,7 @@ ch4 = async(function() s:upsert({5, 5, 5, 5}, {{'+', 4, 1}}) end)
 s.index.i4:drop()
 
 -- Resume the DML requests. Check that they have been aborted.
-errinj.set('ERRINJ_VY_READ_PAGE_TIMEOUT', 0)
+errinj.set('ERRINJ_VY_READ_PAGE_DELAY', false)
 ch1:get()
 ch2:get()
 ch3:get()
-- 
2.11.0

Re: [PATCH 2/2] test: fix vinyl/errinj_ddl failure

[Vladimir Davydov]

Alexander T. confirms that these patches fix vinyl/errinj_stat and
vinyl/errinj_ddl tests. Pushed both patches to master.