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

[Alexander Turenko <alexander.turenko@tarantool.org>]

Hi, Sergei!

I give some general comments below.

Please, update if you are agree with my comments and review the patch
with Vladimir.

WBR, Alexander Turenko.

On Wed, Oct 10, 2018 at 10:56:26AM +0300, Sergei Voronezhskii wrote:
> 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.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 ''");
>  

I think it would be better to allow to reuse this pattern across tests:
place the function into test_run.lua and create a wrapper around
'grep_log', say, 'wait_log'. In this case timeout should not be
hardcoded and always should come from a test. Delay can be hardcoded.

When I need precise time I use clock.monotonic64(), because fiber.time()
value is updated sporadically depending on fiber scheduling / fiber pool
mechanics. Maybe that is not the case and fiber.time() is okay here,
just note to think about.

>  #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)
>  

Now we don't check that 'saving snapshot' does not appear during some
time period. Maybe we should check it after 'making snapshot'.

>  -- restore default options
>  box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
> -- 
> 2.18.0
>