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

[Alexander Turenko]

On Tue, Oct 23, 2018 at 06:00:52PM +0300, Sergei Voronezhskii wrote:
>      Воскресенье, 21 октября 2018, 7:40 +03:00 от Alexander Turenko
>      <alexander.turenko at tarantool.org>:
> 
>    > 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
>    > +test_run:wait_log("default", "making snapshot", 400, 1.0 + PERIOD)
>    >
>    > -- restore default options
>    > box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
>    Cite from the previous review:
>    > > -- 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)
>    > Now we don't check that 'saving snapshot' does not appear during some
>    > time period. Maybe we should check it after 'making snapshot'.
>    It seems you decided to remove the check for some reason you don't
>    mention in
>    the commit message. Am I missed something obvious?
>    In the previous message I just stated that **your** (previous) version
>    of the
>    patch does not check for 'saving snapshot' while the original case
>    does.
>    WBR, Alexander Turenko.
> 
>    Fixed
>    --
>    Sergei Voronezhskii

Cite relevant diff:

--- 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
+not_found = {cmp = function(val) return val == nil end}
+test_run:wait_log("default", "saving snapshot", 400, 1.0 + PERIOD, not_found)
+-- gh-2780 check that scheduled snapshots are performed
+test_run:wait_log("default", "making snapshot", 400, 1.0 + PERIOD)

Now it is more or less okay (except mine comments about wait_cond API
can be found in [1]). But we discussed it with Vladimir and decided to
rewrote the test using explicit mtime check. We should point it for you
before, sorry for that.

I proposed the patch for the test on the
Totktonada/gh-3684-fix-xlog-checkpoint-daemon-test branch.

I didn't enabled parallel run for the xlog test suite within my patch,
because firstly we need to test it intensively, including runs in
parallel with other parallel suites. That seems to be okay, btw.

Please, wait until the patch will be checked in, rebase is_parallel
enabling on top of updated 1.10 branch, test it appropriatelly and
resend the is_parallel enabling patch if things will be good.

[1]: https://github.com/tarantool/test-run/pull/128#pullrequestreview-167924583

WBR, Alexander Turenko.