[tarantool-patches] Re: [PATCH] test: fix box/on_shutdown flakiness

[Alexander Turenko]

LuaJIT's print uses fwrite(..., stdout) + putchar('\n'). As far as I
see, we call triggers right from a signal handler. It [seems][1] that
fwrite() and putchar() should not be used in a signal handler. Maybe we
should mention this in the documentation or move fiber_call() outside of
the signal handler.

The patch is okay. I verified that it does its work: flaky fails are
gone.

Pushed to master and 2.1.

[1]: https://stackoverflow.com/a/16891799/1598057

WBR, Alexander Turenko.

On Wed, Jul 03, 2019 at 04:53:24PM +0300, Serge Petrenko wrote:
> RESEND
> --
> Serge Petrenko
> sergepetrenko at tarantool.org
> 
> 
> 
> 
> > 26 июня 2019 г., в 19:04, Serge Petrenko <sergepetrenko at tarantool.org> написал(а):
> > 
> > Resend for the mailing list
> > --
> > Serge Petrenko
> > sergepetrenko at tarantool.org <mailto:sergepetrenko at tarantool.org>
> > 
> > 
> > 
> > 
> >> 26 июня 2019 г., в 19:02, Serge Petrenko <sergepetrenko at tarantool.org <mailto:sergepetrenko at tarantool.org>> написал(а):
> >> 
> >> Replace prints that indicate on_shutdown trigger execution with
> >> log.warn, which is more reliable. This eliminates occasional test
> >> failures. Also instead of waiting for the server to start and executing
> >> grep_log, wait for the desired log entries to appear with wait_log.
> >> 
> >> Closes #4134
> >> ---
> >> https://github.com/tarantool/tarantool/issues/4134 <https://github.com/tarantool/tarantool/issues/4134>
> >> https://github.com/tarantool/tarantool/tree/sp/gh-4134-on-shutdown-test
> >> 
> >> test/box/on_shutdown.result   | 20 +++++++++++++-------
> >> test/box/on_shutdown.test.lua | 16 +++++++++-------
> >> 2 files changed, 22 insertions(+), 14 deletions(-)
> >> 
> >> diff --git a/test/box/on_shutdown.result b/test/box/on_shutdown.result
> >> index 4992b7de6..ccbdf45cb 100644
> >> --- a/test/box/on_shutdown.result
> >> +++ b/test/box/on_shutdown.result
> >> @@ -1,19 +1,22 @@
> >> env = require('test_run')
> >> ---
> >> ...
> >> +log = require('log')
> >> +---
> >> +...
> >> test_run = env.new()
> >> ---
> >> ...
> >> --
> >> -- gh-1607: on_shutdown triggers.
> >> --
> >> -f = function() print('on_shutdown 1') end
> >> +f = function() log.warn('on_shutdown 1') end
> >> ---
> >> ...
> >> -g = function() print('on_shutdown 2') end
> >> +g = function() log.warn('on_shutdown 2') end
> >> ---
> >> ...
> >> -h = function() print('on_shutdown 3') end
> >> +h = function() log.warn('on_shutdown 3') end
> >> ---
> >> ...
> >> -- Check that on_shutdown triggers may yield
> >> @@ -31,7 +34,7 @@ trig = function()
> >>     box.schema.space.create("shutdown")
> >>     box.space.shutdown:create_index("pk")
> >>     box.space.shutdown:insert{1,2,3}
> >> -    print('on_shutdown 4')
> >> +    log.warn('on_shutdown 4')
> >> end;
> >> ---
> >> ...
> >> @@ -52,8 +55,8 @@ _ = box.ctl.on_shutdown(h, g)
> >> _ = box.ctl.on_shutdown(trig)
> >> ---
> >> ...
> >> -test_run:cmd('restart server default')
> >> -test_run:grep_log('default', 'on_shutdown 1', nil, {noreset=true})
> >> +test_run:cmd('restart server default with wait=False')
> >> +test_run:wait_log('default', 'on_shutdown 1', nil, 30, {noreset=true})
> >> ---
> >> - on_shutdown 1
> >> ...
> >> @@ -108,7 +111,10 @@ test_run:cmd("switch test")
> >> ---
> >> - true
> >> ...
> >> -_ = box.ctl.on_shutdown(function() print("on_shutdown 5") end)
> >> +log = require('log')
> >> +---
> >> +...
> >> +_ = box.ctl.on_shutdown(function() log.warn("on_shutdown 5") end)
> >> ---
> >> ...
> >> -- Check that we don't hang infinitely after os.exit()
> >> diff --git a/test/box/on_shutdown.test.lua b/test/box/on_shutdown.test.lua
> >> index 9c3726dce..2a9143404 100644
> >> --- a/test/box/on_shutdown.test.lua
> >> +++ b/test/box/on_shutdown.test.lua
> >> @@ -1,12 +1,13 @@
> >> env = require('test_run')
> >> +log = require('log')
> >> test_run = env.new()
> >> 
> >> --
> >> -- gh-1607: on_shutdown triggers.
> >> --
> >> -f = function() print('on_shutdown 1') end
> >> -g = function() print('on_shutdown 2') end
> >> -h = function() print('on_shutdown 3') end
> >> +f = function() log.warn('on_shutdown 1') end
> >> +g = function() log.warn('on_shutdown 2') end
> >> +h = function() log.warn('on_shutdown 3') end
> >> -- Check that on_shutdown triggers may yield
> >> -- and perform some complicated actions.
> >> fiber = require('fiber')
> >> @@ -17,7 +18,7 @@ trig = function()
> >>     box.schema.space.create("shutdown")
> >>     box.space.shutdown:create_index("pk")
> >>     box.space.shutdown:insert{1,2,3}
> >> -    print('on_shutdown 4')
> >> +    log.warn('on_shutdown 4')
> >> end;
> >> test_run:cmd("setopt delimiter ''");
> >> _ = box.ctl.on_shutdown(f)
> >> @@ -25,8 +26,8 @@ _ = box.ctl.on_shutdown(g)
> >> -- Check that replacing triggers works
> >> _ = box.ctl.on_shutdown(h, g)
> >> _ = box.ctl.on_shutdown(trig)
> >> -test_run:cmd('restart server default')
> >> -test_run:grep_log('default', 'on_shutdown 1', nil, {noreset=true})
> >> +test_run:cmd('restart server default with wait=False')
> >> +test_run:wait_log('default', 'on_shutdown 1', nil, 30, {noreset=true})
> >> test_run:grep_log('default', 'on_shutdown 2', nil, {noreset=true})
> >> test_run:grep_log('default', 'on_shutdown 3', nil, {noreset=true})
> >> test_run:grep_log('default', 'on_shutdown 4', nil, {noreset=true})
> >> @@ -43,7 +44,8 @@ test_run:cmd("stop server test")
> >> require("fio").unlink(logfile)
> >> test_run:cmd("start server test")
> >> test_run:cmd("switch test")
> >> -_ = box.ctl.on_shutdown(function() print("on_shutdown 5") end)
> >> +log = require('log')
> >> +_ = box.ctl.on_shutdown(function() log.warn("on_shutdown 5") end)
> >> -- Check that we don't hang infinitely after os.exit()
> >> -- even if the following code doesn't yield.
> >> fiber = require("fiber")
> >> -- 
> >> 2.20.1 (Apple Git-117)
> >> 
> > 
>