[Tarantool-patches] [PATCH v2 1/2] test: fix flaky box/net.box_call_blocks_gh-946
Alexander V. Tikhonov
avtikhon at tarantool.org
Thu Jun 25 14:25:10 MSK 2020
Issue:
2020-06-25 14:15:39.094 [26905] main/103/box C> Tarantool 2.4.1-161-g90d2bb8a3
2020-06-25 14:15:39.094 [26905] main/103/box C> log level 5
2020-06-25 14:15:39.094 [26905] main/103/box I> mapping 117440512 bytes for memtx tuple arena...
2020-06-25 14:15:39.094 [26905] main/103/box I> mapping 134217728 bytes for vinyl tuple arena...
2020-06-25 14:15:39.099 [26905] main/103/box I> instance uuid 79a797f5-48f5-4fb4-a191-20414bd1139a
2020-06-25 14:15:39.099 [26905] iproto/101/main I> binary: bound to unix/:(socket)
2020-06-25 14:15:39.100 [26905] main/103/box I> initializing an empty data directory
2020-06-25 14:15:39.126 [26905] main/103/box I> assigned id 1 to replica 79a797f5-48f5-4fb4-a191-20414bd1139a
2020-06-25 14:15:39.126 [26905] main/103/box I> cluster uuid c3f9022f-e3f2-4209-9afa-47a4df6ebf27
2020-06-25 14:15:39.127 [26905] snapshot/101/main I> saving snapshot `/home/avtikhon/Workspaces/tarantool/test/var/001_box/box/00000000000000000000.snap.inprogress'
2020-06-25 14:15:39.129 [26905] snapshot/101/main I> done
2020-06-25 14:15:39.130 [26905] main/103/box I> ready to accept requests
2020-06-25 14:15:39.130 [26905] main/103/box I> set 'log_level' configuration option to 5
2020-06-25 14:15:39.130 [26905] main/106/checkpoint_daemon I> scheduled next checkpoint for Thu Jun 25 15:33:23 2020
2020-06-25 14:15:39.130 [26905] main/103/box I> set 'memtx_memory' configuration option to 107374182
2020-06-25 14:15:39.130 [26905] main/103/box I> set 'listen' configuration option to "\/home\/avtikhon\/Workspaces\/tarantool\/test\/var\/001_box\/box.socket-iproto"
2020-06-25 14:15:39.130 [26905] main/103/box I> set 'log_format' configuration option to "plain"
2020-06-25 14:15:39.130 [26905] main/117/console/unix/:/home/avtikhon/Workspaces/tarantool/test/var/001_box/box.socket-admin I> started
2020-06-25 14:15:39.131 [26905] main C> entering the event loop
2020-06-25 14:15:39.211 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.214 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.214 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.217 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.217 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readahead limit is reached
2020-06-25 14:15:39.221 [26905] iproto iproto.cc:606 W> stopping input on connection fd 23, aka unix/:(socket), peer of unix/:(socket), readah
To fix the issue increased 'readahead' value.
Found issue at the tests running after the current:
2020-06-25 14:11:30.402 [26731] main/103/box C> Tarantool 2.4.1-161-g90d2bb8a3
2020-06-25 14:11:30.402 [26731] main/103/box C> log level 5
2020-06-25 14:11:30.402 [26731] main/103/box I> mapping 117440512 bytes for memtx tuple arena...
2020-06-25 14:11:30.402 [26731] main/103/box I> mapping 134217728 bytes for vinyl tuple arena...
2020-06-25 14:11:30.407 [26731] main/103/box I> instance uuid 7bd70751-835c-40b7-8e90-43f31c8aa09c
2020-06-25 14:11:30.407 [26731] iproto/101/main I> binary: bound to unix/:(socket)
2020-06-25 14:11:30.407 [26731] main/103/box I> initializing an empty data directory
2020-06-25 14:11:30.433 [26731] main/103/box I> assigned id 1 to replica 7bd70751-835c-40b7-8e90-43f31c8aa09c
2020-06-25 14:11:30.433 [26731] main/103/box I> cluster uuid 17fa0851-2b2d-4cfd-8eed-2cfd7a5195c6
2020-06-25 14:11:30.434 [26731] snapshot/101/main I> saving snapshot `/home/avtikhon/Workspaces/tarantool/test/var/001_box/box/00000000000000000000.snap.inprogress'
2020-06-25 14:11:30.443 [26731] snapshot/101/main I> done
2020-06-25 14:11:30.444 [26731] main/103/box I> ready to accept requests
2020-06-25 14:11:30.444 [26731] main/103/box I> set 'log_level' configuration option to 5
2020-06-25 14:11:30.444 [26731] main/106/checkpoint_daemon I> scheduled next checkpoint for Thu Jun 25 16:06:04 2020
2020-06-25 14:11:30.444 [26731] main/103/box I> set 'memtx_memory' configuration option to 107374182
2020-06-25 14:11:30.444 [26731] main/103/box I> set 'listen' configuration option to "\/home\/avtikhon\/Workspaces\/tarantool\/test\/var\/001_box\/box.socket-iproto"
2020-06-25 14:11:30.444 [26731] main/103/box I> set 'log_format' configuration option to "plain"
2020-06-25 14:11:30.445 [26731] main/117/console/unix/:/home/avtikhon/Workspaces/tarantool/test/var/001_box/box.socket-admin I> started
2020-06-25 14:11:30.445 [26731] main C> entering the event loop
2020-06-25 14:11:30.479 [26731] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-25 14:11:30.569 [26731] main/119/console/unix/: I> set 'readahead' configuration option to 16320
2020-06-25 14:11:30.582 [26731] main/119/console/unix/: I> set 'readahead' configuration option to 128
2020-06-25 14:11:30.587 [26731] main/119/console/unix/: I> set 'readahead' configuration option to 102400
2020-06-25 14:11:30.589 [26731] main/420/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.594 [26731] main/422/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.599 [26731] main/423/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.605 [26731] main/424/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.615 [26731] main/425/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.625 [26731] main/426/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.635 [26731] main/427/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.641 [26731] main/428/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.649 [26731] main/429/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.662 [26731] main/430/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.666 [26731] main/431/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.674 [26731] main/433/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.681 [26731] main/434/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.688 [26731] main/435/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.693 [26731] main/432/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.694 [26731] main/119/console/unix/: utils.c:1005 E> LuajitError: [string "function on_disconnect() disconnected = true ..."]:1: assign to undeclared variable 'disconnected'
2020-06-25 14:11:30.697 [26731] main/436/console/unix/: I> set 'readahead' configuration option to 16320
Found that the root cause of the issue, that both tests run on the same
worker, in this case function on_disconnected must be cleaned. Also clean
up of the test at its end improved.
Part of #5082
---
Github: https://github.com/tarantool/tarantool/tree/avtikhon/gh-5082-net-box-readahead
Issue: https://github.com/tarantool/tarantool/issues/5082
test/box/net.box_call_blocks_gh-946.result | 30 ++++++++++++++++++++
test/box/net.box_call_blocks_gh-946.test.lua | 12 ++++++++
2 files changed, 42 insertions(+)
diff --git a/test/box/net.box_call_blocks_gh-946.result b/test/box/net.box_call_blocks_gh-946.result
index 2f6d5fcf2..d9d868ce1 100644
--- a/test/box/net.box_call_blocks_gh-946.result
+++ b/test/box/net.box_call_blocks_gh-946.result
@@ -11,6 +11,12 @@ test_run:cmd('create server connecter with script = "box/proxy.lua"')
---
- true
...
+readahead = box.cfg.readahead
+---
+...
+box.cfg{readahead = 100 * 1024}
+---
+...
--
-- gh-946: long polling CALL blocks input
--
@@ -117,3 +123,27 @@ box.session.on_disconnect(on_disconnect) == on_disconnect
---
- true
...
+c:close()
+---
+...
+box.schema.user.revoke('guest', 'execute', 'function', 'fast_call')
+---
+...
+box.schema.user.revoke('guest', 'execute', 'function', 'long_call')
+---
+...
+box.schema.user.revoke('guest', 'execute', 'function', 'wait_signal')
+---
+...
+box.schema.func.drop('fast_call')
+---
+...
+box.schema.func.drop('long_call')
+---
+...
+box.schema.func.drop('wait_signal')
+---
+...
+box.cfg{readahead = readahead}
+---
+...
diff --git a/test/box/net.box_call_blocks_gh-946.test.lua b/test/box/net.box_call_blocks_gh-946.test.lua
index 541541eda..951919737 100644
--- a/test/box/net.box_call_blocks_gh-946.test.lua
+++ b/test/box/net.box_call_blocks_gh-946.test.lua
@@ -5,6 +5,9 @@ net = require('net.box')
test_run:cmd('create server connecter with script = "box/proxy.lua"')
+readahead = box.cfg.readahead
+box.cfg{readahead = 100 * 1024}
+
--
-- gh-946: long polling CALL blocks input
--
@@ -61,3 +64,12 @@ collectgarbage('collect')
fiber.sleep(0)
box.session.on_disconnect(on_disconnect) == on_disconnect
+
+c:close()
+box.schema.user.revoke('guest', 'execute', 'function', 'fast_call')
+box.schema.user.revoke('guest', 'execute', 'function', 'long_call')
+box.schema.user.revoke('guest', 'execute', 'function', 'wait_signal')
+box.schema.func.drop('fast_call')
+box.schema.func.drop('long_call')
+box.schema.func.drop('wait_signal')
+box.cfg{readahead = readahead}
--
2.17.1
More information about the Tarantool-patches
mailing list