[PATCH 1/2] test: wait until expected value appear in log

[Sergei Voronezhskii]

Sleep for the constant time can't fit the case when we need to wait for
snapshot. System load may change app timings and we got flaky test.
Need to check logfile with delay until timeout or log has expected
entry.

Fixes #3684

Part of #2436, #3232
---
 test/xlog/checkpoint_daemon.result   | 22 +++++++++++++++++-----
 test/xlog/checkpoint_daemon.test.lua | 21 ++++++++++++++++-----
 2 files changed, 33 insertions(+), 10 deletions(-)

diff --git a/test/xlog/checkpoint_daemon.result b/test/xlog/checkpoint_daemon.result
index d5ed666f2..e712a0f11 100644
--- a/test/xlog/checkpoint_daemon.result
+++ b/test/xlog/checkpoint_daemon.result
@@ -73,6 +73,21 @@ for i = 1, 100 do
 end;
 ---
 ...
+function wait_cond(fn, timeout, delay)
+    timeout = timeout or 1.0
+    delay = delay or 0.001
+    local t1 = fiber.time()
+    while not fn() do
+        local work_time = fiber.time() - t1
+        if work_time > timeout then
+            return false
+        end
+        fiber.sleep(delay)
+    end
+    return true
+end;
+---
+...
 test_run:cmd("setopt delimiter ''");
 ---
 - true
@@ -90,15 +105,12 @@ fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
 - true
 ...
 -- gh-2780 check that scheduled snapshots are performed
-fiber.sleep(3 * PERIOD)
----
-...
 -- check that it's not first snapshot
-test_run:grep_log("default", "saving snapshot", 400) == nil
+wait_cond(function() return test_run:grep_log("default", "saving snapshot", 400) == nil end)
 ---
 - true
 ...
-test_run:grep_log("default", "making snapshot", 400) ~= nil
+wait_cond(function() return test_run:grep_log("default", "making snapshot", 400) ~= nil end)
 ---
 - true
 ...
diff --git a/test/xlog/checkpoint_daemon.test.lua b/test/xlog/checkpoint_daemon.test.lua
index 4a0aafa84..02f2768d9 100644
--- a/test/xlog/checkpoint_daemon.test.lua
+++ b/test/xlog/checkpoint_daemon.test.lua
@@ -44,9 +44,21 @@ for i = 1, 100 do
     end
 end;
 
-test_run:cmd("setopt delimiter ''");
-
+function wait_cond(fn, timeout, delay)
+    timeout = timeout or 1.0
+    delay = delay or 0.001
+    local t1 = fiber.time()
+    while not fn() do
+        local work_time = fiber.time() - t1
+        if work_time > timeout then
+            return false
+        end
+        fiber.sleep(delay)
+    end
+    return true
+end;
 
+test_run:cmd("setopt delimiter ''");
 
 #snaps == 2 or snaps
 #xlogs > 0
@@ -54,10 +66,9 @@ test_run:cmd("setopt delimiter ''");
 fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
 
 -- gh-2780 check that scheduled snapshots are performed
-fiber.sleep(3 * PERIOD)
 -- check that it's not first snapshot
-test_run:grep_log("default", "saving snapshot", 400) == nil
-test_run:grep_log("default", "making snapshot", 400) ~= nil
+wait_cond(function() return test_run:grep_log("default", "saving snapshot", 400) == nil end)
+wait_cond(function() return test_run:grep_log("default", "making snapshot", 400) ~= nil end)
 
 -- restore default options
 box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
-- 
2.18.0