From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtp3.mail.ru (smtp3.mail.ru [94.100.179.58]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dev.tarantool.org (Postfix) with ESMTPS id 212F042EF5C for ; Thu, 25 Jun 2020 14:25:14 +0300 (MSK) From: "Alexander V. Tikhonov" Date: Thu, 25 Jun 2020 14:25:10 +0300 Message-Id: <1bc869413c7d116ba5fcdd2a05c756729fedd7d4.1593084206.git.avtikhon@tarantool.org> Subject: [Tarantool-patches] [PATCH v2 1/2] test: fix flaky box/net.box_call_blocks_gh-946 List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Kirill Yukhin , Alexander Turenko Cc: tarantool-patches@dev.tarantool.org 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