[PATCH v2 0/2] Rework on_shutdown test for better stability.

[PATCH v2 0/2] Rework on_shutdown test for better stability.

[Serge Petrenko]

https://github.com/tarantool/tarantool/issues/4134
https://github.com/tarantool/tarantool/tree/sp/gh-4134-rework-on-shutdown-tests

Changes in v2:
  - separated a single patch into two.

First patch extracts on_shutdown subtest from box/misc.test.lua into a separate file:
box/on_shutdown.test.lua

Second patch alters on_shutdown tests slightly to make them less dependent on
hardcoded timeouts (sleeps, etc.), which are exceeded under high load causing
test failures.

Serge Petrenko (2):
  test: extract on_shutdown tests from box/misc
  test: rework box/on_shutdown test

 test/box/misc.result          | 161 ---------------------------------
 test/box/misc.test.lua        |  61 -------------
 test/box/on_shutdown.result   | 163 ++++++++++++++++++++++++++++++++++
 test/box/on_shutdown.test.lua |  65 ++++++++++++++
 4 files changed, 228 insertions(+), 222 deletions(-)
 create mode 100644 test/box/on_shutdown.result
 create mode 100644 test/box/on_shutdown.test.lua

-- 
2.20.1 (Apple Git-117)

[PATCH v2 1/2] test: extract on_shutdown tests from box/misc

[Serge Petrenko]

This part of the test is flaky when tests are run in parallel, besides,
it is quite big on its own, so extract it into a separate file to add
more flexibility in running tests and to make finding problems easier.

Part of #4134
---
 test/box/misc.result          | 161 --------------------------------
 test/box/misc.test.lua        |  61 -------------
 test/box/on_shutdown.result   | 167 ++++++++++++++++++++++++++++++++++
 test/box/on_shutdown.test.lua |  64 +++++++++++++
 4 files changed, 231 insertions(+), 222 deletions(-)
 create mode 100644 test/box/on_shutdown.result
 create mode 100644 test/box/on_shutdown.test.lua

diff --git a/test/box/misc.result b/test/box/misc.result
index e2b618c9c..a1f7a0990 100644
--- a/test/box/misc.result
+++ b/test/box/misc.result
@@ -1269,164 +1269,3 @@ box.cfg{too_long_threshold = too_long_threshold}
 s:drop()
 ---
 ...
---
--- 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
----
-...
--- Check that on_shutdown triggers may yield
--- and perform some complicated actions.
-fiber = require('fiber')
----
-...
-test_run:cmd("setopt delimiter ';'")
----
-- true
-...
-trig = function()
-    fiber.sleep(0.01)
-    fiber.yield()
-    box.schema.space.create("shutdown")
-    box.space.shutdown:create_index("pk")
-    box.space.shutdown:insert{1,2,3}
-    print('on_shutdown 4')
-end;
----
-...
-test_run:cmd("setopt delimiter ''");
----
-- true
-...
-_ = box.ctl.on_shutdown(f)
----
-...
-_ = 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})
----
-- on_shutdown 1
-...
-test_run:grep_log('default', 'on_shutdown 2', nil, {noreset=true})
----
-- null
-...
-test_run:grep_log('default', 'on_shutdown 3', nil, {noreset=true})
----
-- on_shutdown 3
-...
-test_run:grep_log('default', 'on_shutdown 4', nil, {noreset=true})
----
-- on_shutdown 4
-...
-box.space.shutdown:select{}
----
-- - [1, 2, 3]
-...
-box.space.shutdown:drop()
----
-...
--- Check that os.exit invokes triggers
-fiber = require("fiber")
----
-...
-test_run:cmd("create server test with script='box/proxy.lua'")
----
-- true
-...
-test_run:cmd("start server test")
----
-- true
-...
-logfile = test_run:eval("test", "box.cfg.log")[1]
----
-...
-test_run:cmd("stop server test")
----
-- true
-...
--- clean up any leftover logs
-require("fio").unlink(logfile)
----
-- true
-...
-test_run:cmd("start server test")
----
-- true
-...
-test_run:cmd("switch test")
----
-- true
-...
-_ = box.ctl.on_shutdown(function() print("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")
----
-...
-_ = fiber.create(function() fiber.sleep(0.05) os.exit() while true do end end)
----
-...
-test_run:cmd("switch default")
----
-- true
-...
-fiber.sleep(0.1)
----
-...
--- The server should be already stopped by os.exit(),
--- but start doesn't work without a prior call to stop.
-test_run:cmd("stop server test")
----
-- true
-...
-test_run:cmd("start server test")
----
-- true
-...
-test_run:cmd("switch test")
----
-- true
-...
-test_run:grep_log('test', 'on_shutdown 5', nil, {noreset=true})
----
-- on_shutdown 5
-...
--- make sure we exited because of os.exit(), not a signal.
-test_run:grep_log('test', 'signal', nil, {noreset=true})
----
-- null
-...
-test_run:cmd("switch default")
----
-- true
-...
-test_run:cmd("stop server test")
----
-- true
-...
-test_run:cmd("cleanup server test")
----
-- true
-...
-test_run:cmd("delete server test")
----
-- true
-...
diff --git a/test/box/misc.test.lua b/test/box/misc.test.lua
index 18128b299..75d937e2a 100644
--- a/test/box/misc.test.lua
+++ b/test/box/misc.test.lua
@@ -353,64 +353,3 @@ lsn == expected_lsn
 box.cfg{too_long_threshold = too_long_threshold}
 s:drop()
 
---
--- 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
--- Check that on_shutdown triggers may yield
--- and perform some complicated actions.
-fiber = require('fiber')
-test_run:cmd("setopt delimiter ';'")
-trig = function()
-    fiber.sleep(0.01)
-    fiber.yield()
-    box.schema.space.create("shutdown")
-    box.space.shutdown:create_index("pk")
-    box.space.shutdown:insert{1,2,3}
-    print('on_shutdown 4')
-end;
-test_run:cmd("setopt delimiter ''");
-_ = box.ctl.on_shutdown(f)
-_ = 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: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})
-box.space.shutdown:select{}
-box.space.shutdown:drop()
-
--- Check that os.exit invokes triggers
-fiber = require("fiber")
-test_run:cmd("create server test with script='box/proxy.lua'")
-test_run:cmd("start server test")
-logfile = test_run:eval("test", "box.cfg.log")[1]
-test_run:cmd("stop server test")
--- clean up any leftover logs
-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)
--- Check that we don't hang infinitely after os.exit()
--- even if the following code doesn't yield.
-fiber = require("fiber")
-_ = fiber.create(function() fiber.sleep(0.05) os.exit() while true do end end)
-test_run:cmd("switch default")
-fiber.sleep(0.1)
--- The server should be already stopped by os.exit(),
--- but start doesn't work without a prior call to stop.
-test_run:cmd("stop server test")
-test_run:cmd("start server test")
-test_run:cmd("switch test")
-test_run:grep_log('test', 'on_shutdown 5', nil, {noreset=true})
--- make sure we exited because of os.exit(), not a signal.
-test_run:grep_log('test', 'signal', nil, {noreset=true})
-test_run:cmd("switch default")
-test_run:cmd("stop server test")
-test_run:cmd("cleanup server test")
-test_run:cmd("delete server test")
diff --git a/test/box/on_shutdown.result b/test/box/on_shutdown.result
new file mode 100644
index 000000000..2a9f3fe17
--- /dev/null
+++ b/test/box/on_shutdown.result
@@ -0,0 +1,167 @@
+env = require('test_run')
+---
+...
+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
+---
+...
+-- Check that on_shutdown triggers may yield
+-- and perform some complicated actions.
+fiber = require('fiber')
+---
+...
+test_run:cmd("setopt delimiter ';'")
+---
+- true
+...
+trig = function()
+    fiber.sleep(0.01)
+    fiber.yield()
+    box.schema.space.create("shutdown")
+    box.space.shutdown:create_index("pk")
+    box.space.shutdown:insert{1,2,3}
+    print('on_shutdown 4')
+end;
+---
+...
+test_run:cmd("setopt delimiter ''");
+---
+- true
+...
+_ = box.ctl.on_shutdown(f)
+---
+...
+_ = 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})
+---
+- on_shutdown 1
+...
+test_run:grep_log('default', 'on_shutdown 2', nil, {noreset=true})
+---
+- null
+...
+test_run:grep_log('default', 'on_shutdown 3', nil, {noreset=true})
+---
+- on_shutdown 3
+...
+test_run:grep_log('default', 'on_shutdown 4', nil, {noreset=true})
+---
+- on_shutdown 4
+...
+box.space.shutdown:select{}
+---
+- - [1, 2, 3]
+...
+box.space.shutdown:drop()
+---
+...
+-- Check that os.exit invokes triggers
+fiber = require("fiber")
+---
+...
+test_run:cmd("create server test with script='box/proxy.lua'")
+---
+- true
+...
+test_run:cmd("start server test")
+---
+- true
+...
+logfile = test_run:eval("test", "box.cfg.log")[1]
+---
+...
+test_run:cmd("stop server test")
+---
+- true
+...
+-- clean up any leftover logs
+require("fio").unlink(logfile)
+---
+- true
+...
+test_run:cmd("start server test")
+---
+- true
+...
+test_run:cmd("switch test")
+---
+- true
+...
+_ = box.ctl.on_shutdown(function() print("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")
+---
+...
+_ = fiber.create(function() fiber.sleep(0.05) os.exit() while true do end end)
+---
+...
+test_run:cmd("switch default")
+---
+- true
+...
+fiber.sleep(0.1)
+---
+...
+-- The server should be already stopped by os.exit(),
+-- but start doesn't work without a prior call to stop.
+test_run:cmd("stop server test")
+---
+- true
+...
+test_run:cmd("start server test")
+---
+- true
+...
+test_run:cmd("switch test")
+---
+- true
+...
+test_run:grep_log('test', 'on_shutdown 5', nil, {noreset=true})
+---
+- on_shutdown 5
+...
+-- make sure we exited because of os.exit(), not a signal.
+test_run:grep_log('test', 'signal', nil, {noreset=true})
+---
+- null
+...
+test_run:cmd("switch default")
+---
+- true
+...
+test_run:cmd("stop server test")
+---
+- true
+...
+test_run:cmd("cleanup server test")
+---
+- true
+...
+test_run:cmd("delete server test")
+---
+- true
+...
diff --git a/test/box/on_shutdown.test.lua b/test/box/on_shutdown.test.lua
new file mode 100644
index 000000000..b2247cf13
--- /dev/null
+++ b/test/box/on_shutdown.test.lua
@@ -0,0 +1,64 @@
+env = require('test_run')
+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
+-- Check that on_shutdown triggers may yield
+-- and perform some complicated actions.
+fiber = require('fiber')
+test_run:cmd("setopt delimiter ';'")
+trig = function()
+    fiber.sleep(0.01)
+    fiber.yield()
+    box.schema.space.create("shutdown")
+    box.space.shutdown:create_index("pk")
+    box.space.shutdown:insert{1,2,3}
+    print('on_shutdown 4')
+end;
+test_run:cmd("setopt delimiter ''");
+_ = box.ctl.on_shutdown(f)
+_ = 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: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})
+box.space.shutdown:select{}
+box.space.shutdown:drop()
+
+-- Check that os.exit invokes triggers
+fiber = require("fiber")
+test_run:cmd("create server test with script='box/proxy.lua'")
+test_run:cmd("start server test")
+logfile = test_run:eval("test", "box.cfg.log")[1]
+test_run:cmd("stop server test")
+-- clean up any leftover logs
+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)
+-- Check that we don't hang infinitely after os.exit()
+-- even if the following code doesn't yield.
+fiber = require("fiber")
+_ = fiber.create(function() fiber.sleep(0.05) os.exit() while true do end end)
+test_run:cmd("switch default")
+fiber.sleep(0.1)
+-- The server should be already stopped by os.exit(),
+-- but start doesn't work without a prior call to stop.
+test_run:cmd("stop server test")
+test_run:cmd("start server test")
+test_run:cmd("switch test")
+test_run:grep_log('test', 'on_shutdown 5', nil, {noreset=true})
+-- make sure we exited because of os.exit(), not a signal.
+test_run:grep_log('test', 'signal', nil, {noreset=true})
+test_run:cmd("switch default")
+test_run:cmd("stop server test")
+test_run:cmd("cleanup server test")
+test_run:cmd("delete server test")
-- 
2.20.1 (Apple Git-117)

[PATCH v2 2/2] test: rework box/on_shutdown test

[Serge Petrenko]

The test is flaky under high load (e.g. when is run in parallel with a
lot of workers). Make it less dependent on arbitrary timeouts to improve
stability.

Part of #4134
---
 test/box/on_shutdown.result   | 22 +++++++++-------------
 test/box/on_shutdown.test.lua | 11 ++++++-----
 2 files changed, 15 insertions(+), 18 deletions(-)

diff --git a/test/box/on_shutdown.result b/test/box/on_shutdown.result
index 2a9f3fe17..4992b7de6 100644
--- a/test/box/on_shutdown.result
+++ b/test/box/on_shutdown.result
@@ -76,7 +76,7 @@ box.space.shutdown:select{}
 box.space.shutdown:drop()
 ---
 ...
--- Check that os.exit invokes triggers
+-- Check that os.exit invokes on_shutdown triggers
 fiber = require("fiber")
 ---
 ...
@@ -116,13 +116,17 @@ _ = box.ctl.on_shutdown(function() print("on_shutdown 5") end)
 fiber = require("fiber")
 ---
 ...
-_ = fiber.create(function() fiber.sleep(0.05) os.exit() while true do end end)
----
-...
 test_run:cmd("switch default")
 ---
 - true
 ...
+-- eval the command on the 'test' instance while we're on default
+-- instance to make sure test_run doesn't lose connection to the
+-- shutting down instance.
+test_run:eval("test", "_ = fiber.new(function() os.exit() while true do end end)")
+---
+- []
+...
 fiber.sleep(0.1)
 ---
 ...
@@ -136,11 +140,7 @@ test_run:cmd("start server test")
 ---
 - true
 ...
-test_run:cmd("switch test")
----
-- true
-...
-test_run:grep_log('test', 'on_shutdown 5', nil, {noreset=true})
+test_run:wait_log('test', 'on_shutdown 5', nil, 30, {noreset=true})
 ---
 - on_shutdown 5
 ...
@@ -149,10 +149,6 @@ test_run:grep_log('test', 'signal', nil, {noreset=true})
 ---
 - null
 ...
-test_run:cmd("switch default")
----
-- true
-...
 test_run:cmd("stop server test")
 ---
 - true
diff --git a/test/box/on_shutdown.test.lua b/test/box/on_shutdown.test.lua
index b2247cf13..9c3726dce 100644
--- a/test/box/on_shutdown.test.lua
+++ b/test/box/on_shutdown.test.lua
@@ -33,7 +33,7 @@ test_run:grep_log('default', 'on_shutdown 4', nil, {noreset=true})
 box.space.shutdown:select{}
 box.space.shutdown:drop()
 
--- Check that os.exit invokes triggers
+-- Check that os.exit invokes on_shutdown triggers
 fiber = require("fiber")
 test_run:cmd("create server test with script='box/proxy.lua'")
 test_run:cmd("start server test")
@@ -47,18 +47,19 @@ _ = box.ctl.on_shutdown(function() print("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")
-_ = fiber.create(function() fiber.sleep(0.05) os.exit() while true do end end)
 test_run:cmd("switch default")
+-- eval the command on the 'test' instance while we're on default
+-- instance to make sure test_run doesn't lose connection to the
+-- shutting down instance.
+test_run:eval("test", "_ = fiber.new(function() os.exit() while true do end end)")
 fiber.sleep(0.1)
 -- The server should be already stopped by os.exit(),
 -- but start doesn't work without a prior call to stop.
 test_run:cmd("stop server test")
 test_run:cmd("start server test")
-test_run:cmd("switch test")
-test_run:grep_log('test', 'on_shutdown 5', nil, {noreset=true})
+test_run:wait_log('test', 'on_shutdown 5', nil, 30, {noreset=true})
 -- make sure we exited because of os.exit(), not a signal.
 test_run:grep_log('test', 'signal', nil, {noreset=true})
-test_run:cmd("switch default")
 test_run:cmd("stop server test")
 test_run:cmd("cleanup server test")
 test_run:cmd("delete server test")
-- 
2.20.1 (Apple Git-117)

Re: [PATCH v2 0/2] Rework on_shutdown test for better stability.

[Vladimir Davydov]

On Fri, Apr 12, 2019 at 05:33:38PM +0300, Serge Petrenko wrote:
>   test: extract on_shutdown tests from box/misc
>   test: rework box/on_shutdown test

Pushed to master and 2.1.