[PATCH 2/2] test: rewrote xlog/checkpoint_daemon.test.lua

[Alexander Turenko]

Updated the test case for #2780 to check a last snapshot file
modification time instead of search log messages.

The test was flaky, because of small timeouts on Linux, but now we
spinning on a condition check to achieve both stable results and fast
execution.

Follows up #2780.
Fixes #3684.
---
 test/xlog/checkpoint_daemon.result   | 90 ++++++++++++++++++++--------
 test/xlog/checkpoint_daemon.test.lua | 84 +++++++++++++++++---------
 2 files changed, 121 insertions(+), 53 deletions(-)

diff --git a/test/xlog/checkpoint_daemon.result b/test/xlog/checkpoint_daemon.result
index d5ed666f2..3a75137d2 100644
--- a/test/xlog/checkpoint_daemon.result
+++ b/test/xlog/checkpoint_daemon.result
@@ -19,10 +19,10 @@ test_run:cleanup_cluster()
 box.cfg{checkpoint_interval = 0}
 ---
 ...
-PERIOD = 0.03
+PERIOD = jit.os == 'Linux' and 0.03 or 1.5
 ---
 ...
-if jit.os ~= 'Linux' then PERIOD = 1.5 end
+WAIT_COND_TIMEOUT = 10
 ---
 ...
 space = box.schema.space.create('checkpoint_daemon')
@@ -31,6 +31,50 @@ space = box.schema.space.create('checkpoint_daemon')
 index = space:create_index('pk', { type = 'tree', parts = { 1, 'unsigned' }})
 ---
 ...
+test_run:cmd("setopt delimiter ';'")
+---
+- true
+...
+-- wait_snapshot* functions update these variables.
+snaps = {};
+---
+...
+xlogs = {};
+---
+...
+-- Wait until tarantool creates a snapshot containing current
+-- data slice.
+function wait_snapshot(timeout)
+    snaps = {}
+    xlogs = {}
+    local signature_str = tostring(box.info.signature)
+    signature_str = string.rjust(signature_str, 20, '0')
+    local exp_snap_filename = string.format('%s.snap', signature_str)
+    return test_run:wait_cond(function()
+        snaps = fio.glob(fio.pathjoin(box.cfg.memtx_dir, '*.snap'))
+        xlogs = fio.glob(fio.pathjoin(box.cfg.wal_dir, '*.xlog'))
+        return fio.basename(snaps[#snaps]) == exp_snap_filename
+    end, timeout)
+end;
+---
+...
+-- Wait until snapshots count will be equal to the
+-- checkpoint_count option.
+function wait_snapshot_gc(timeout)
+    snaps = {}
+    xlogs = {}
+    return test_run:wait_cond(function()
+        snaps = fio.glob(fio.pathjoin(box.cfg.memtx_dir, '*.snap'))
+        xlogs = fio.glob(fio.pathjoin(box.cfg.wal_dir, '*.xlog'))
+        return #snaps == box.cfg.checkpoint_count
+    end, timeout)
+end;
+---
+...
+test_run:cmd("setopt delimiter ''");
+---
+- true
+...
 box.cfg{checkpoint_interval = PERIOD, checkpoint_count = 2 }
 ---
 ...
@@ -45,9 +89,9 @@ for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
 for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
 ---
 ...
--- wait for last snapshot
-fiber.sleep(1.5 * PERIOD)
+wait_snapshot(WAIT_COND_TIMEOUT)
 ---
+- true
 ...
 -- third xlog
 for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
@@ -57,23 +101,11 @@ for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
 for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
 ---
 ...
--- wait for last snapshot
-test_run:cmd("setopt delimiter ';'")
+wait_snapshot(WAIT_COND_TIMEOUT)
 ---
 - true
 ...
-for i = 1, 100 do
-    fiber.sleep(PERIOD)
-    snaps = fio.glob(fio.pathjoin(box.cfg.memtx_dir, '*.snap'))
-    xlogs = fio.glob(fio.pathjoin(box.cfg.wal_dir, '*.xlog'))
-
-    if #snaps == 2 then
-        break
-    end
-end;
----
-...
-test_run:cmd("setopt delimiter ''");
+wait_snapshot_gc(WAIT_COND_TIMEOUT)
 ---
 - true
 ...
@@ -85,20 +117,30 @@ test_run:cmd("setopt delimiter ''");
 ---
 - true
 ...
-fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
+-- gh-2780: check that a last snapshot mtime will be changed at
+-- least two times.
+test_run:cmd("setopt delimiter ';'")
 ---
 - true
 ...
--- gh-2780 check that scheduled snapshots are performed
-fiber.sleep(3 * PERIOD)
+last_mtime = fio.stat(snaps[#snaps]).mtime;
 ---
 ...
--- check that it's not first snapshot
-test_run:grep_log("default", "saving snapshot", 400) == nil
+mtime_changes_cnt = 0;
+---
+...
+test_run:wait_cond(function()
+    local mtime = fio.stat(snaps[#snaps]).mtime
+    if mtime ~= last_mtime then
+        mtime_changes_cnt = mtime_changes_cnt + 1
+        last_mtime = mtime
+    end
+    return mtime_changes_cnt == 2
+end, WAIT_COND_TIMEOUT);
 ---
 - true
 ...
-test_run:grep_log("default", "making snapshot", 400) ~= nil
+test_run:cmd("setopt delimiter ''");
 ---
 - true
 ...
diff --git a/test/xlog/checkpoint_daemon.test.lua b/test/xlog/checkpoint_daemon.test.lua
index 4a0aafa84..f34906217 100644
--- a/test/xlog/checkpoint_daemon.test.lua
+++ b/test/xlog/checkpoint_daemon.test.lua
@@ -8,13 +8,46 @@ test_run:cleanup_cluster()
 
 box.cfg{checkpoint_interval = 0}
 
-PERIOD = 0.03
-if jit.os ~= 'Linux' then PERIOD = 1.5 end
-
+PERIOD = jit.os == 'Linux' and 0.03 or 1.5
+WAIT_COND_TIMEOUT = 10
 
 space = box.schema.space.create('checkpoint_daemon')
 index = space:create_index('pk', { type = 'tree', parts = { 1, 'unsigned' }})
 
+test_run:cmd("setopt delimiter ';'")
+
+-- wait_snapshot* functions update these variables.
+snaps = {};
+xlogs = {};
+
+-- Wait until tarantool creates a snapshot containing current
+-- data slice.
+function wait_snapshot(timeout)
+    snaps = {}
+    xlogs = {}
+    local signature_str = tostring(box.info.signature)
+    signature_str = string.rjust(signature_str, 20, '0')
+    local exp_snap_filename = string.format('%s.snap', signature_str)
+    return test_run:wait_cond(function()
+        snaps = fio.glob(fio.pathjoin(box.cfg.memtx_dir, '*.snap'))
+        xlogs = fio.glob(fio.pathjoin(box.cfg.wal_dir, '*.xlog'))
+        return fio.basename(snaps[#snaps]) == exp_snap_filename
+    end, timeout)
+end;
+
+-- Wait until snapshots count will be equal to the
+-- checkpoint_count option.
+function wait_snapshot_gc(timeout)
+    snaps = {}
+    xlogs = {}
+    return test_run:wait_cond(function()
+        snaps = fio.glob(fio.pathjoin(box.cfg.memtx_dir, '*.snap'))
+        xlogs = fio.glob(fio.pathjoin(box.cfg.wal_dir, '*.xlog'))
+        return #snaps == box.cfg.checkpoint_count
+    end, timeout)
+end;
+
+test_run:cmd("setopt delimiter ''");
 
 box.cfg{checkpoint_interval = PERIOD, checkpoint_count = 2 }
 
@@ -23,41 +56,34 @@ no = 1
 for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
 -- second xlog
 for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
--- wait for last snapshot
-fiber.sleep(1.5 * PERIOD)
+
+wait_snapshot(WAIT_COND_TIMEOUT)
+
 -- third xlog
 for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
 -- fourth xlog
 for i = 1, box.cfg.rows_per_wal + 10 do space:insert { no } no = no + 1 end
 
--- wait for last snapshot
-
-test_run:cmd("setopt delimiter ';'")
-
-for i = 1, 100 do
-    fiber.sleep(PERIOD)
-    snaps = fio.glob(fio.pathjoin(box.cfg.memtx_dir, '*.snap'))
-    xlogs = fio.glob(fio.pathjoin(box.cfg.wal_dir, '*.xlog'))
-
-    if #snaps == 2 then
-        break
-    end
-end;
-
-test_run:cmd("setopt delimiter ''");
-
-
+wait_snapshot(WAIT_COND_TIMEOUT)
+wait_snapshot_gc(WAIT_COND_TIMEOUT)
 
 #snaps == 2 or snaps
 #xlogs > 0
 
-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
+-- gh-2780: check that a last snapshot mtime will be changed at
+-- least two times.
+test_run:cmd("setopt delimiter ';'")
+last_mtime = fio.stat(snaps[#snaps]).mtime;
+mtime_changes_cnt = 0;
+test_run:wait_cond(function()
+    local mtime = fio.stat(snaps[#snaps]).mtime
+    if mtime ~= last_mtime then
+        mtime_changes_cnt = mtime_changes_cnt + 1
+        last_mtime = mtime
+    end
+    return mtime_changes_cnt == 2
+end, WAIT_COND_TIMEOUT);
+test_run:cmd("setopt delimiter ''");
 
 -- restore default options
 box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
-- 
2.19.1