test: binary/binary-boundary.test.py test gets stuck from time to time

[ylobankov]

From time to time the binary/binary-boundary.test.py test gets stuck:

$ make test-memcached
[  3%] Built target generate_proto_txt_parser_c
[ 11%] Built target msgpuck
[ 55%] Built target small
[100%] Built target internalso
Started ./test-run.py --force
Collecting tests in 'binary': memcached binary tests.
Found 4 tests.
Collecting tests in 'capable': memcapable integration.
Found 2 tests.
Collecting tests in 'sasl': memcached binary sasl tests.
Found 1 tests.
Collecting tests in 'text': memcached text tests.
Found 10 tests.
Installing the server ...
    Found executable at /usr/bin/tarantool
    Found tarantoolctl at  /usr/bin/tarantoolctl
    Creating and populating working directory in /home/ubuntu/actions-runner/_work/tarantool/tarantool/test/var ...
    Found old vardir, deleting ...
Starting the server ...
Starting /home/ubuntu/actions-runner/_work/tarantool/tarantool/test/var/binary.lua
Tarantool 2.10.0-beta1-225-g816e1dbd1
Target: Linux-x86_64-RelWithDebInfo
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr -DENABLE_BACKTRACE=ON
Compiler: /usr/bin/cc /usr/lib/ccache/g++
C_FLAGS:-g -O2 -fdebug-prefix-map=/build/tarantool-2.10.0~beta1.225.dev=. -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-gnu-alignof-expression -fno-gnu89-inline -Wno-cast-function-type
CXX_FLAGS:-g -O2 -fdebug-prefix-map=/build/tarantool-2.10.0~beta1.225.dev=. -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c++11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type
================================================================================
TEST                                            PARAMS		RESULT
---------------------------------------------------------------------------
binary/binary-boundary.test.py

Looks like we are hanging at some iteration because the test/var/binary-boundary.result file shows as follows:

#---------------------# test protocol boundary overruns #---------------------#
iteration 1900
iteration 1901
iteration 1902
iteration 1903
iteration 1904
iteration 1905
iteration 1906
iteration 1907
iteration 1908
iteration 1909
iteration 1910
iteration 1911
iteration 1912
iteration 1913
iteration 1914
iteration 1915
iteration 1916
iteration 1917
iteration 1918
iteration 1919
iteration 1920
iteration 1921
iteration 1922
iteration 1923
iteration 1924
iteration 1925
iteration 1926
iteration 1927
iteration 1928
iteration 1929
iteration 1930
iteration 1931
iteration 1932
iteration 1933
iteration 1934
iteration 1935
iteration 1936
iteration 1937
iteration 1938
iteration 1939
iteration 1940
iteration 1941
iteration 1942
iteration 1943
iteration 1944
iteration 1945
iteration 1946
iteration 1947
iteration 1948
iteration 1949
iteration 1950
iteration 1951
iteration 1952
iteration 1953
iteration 1954

Unfortunately, I don't have exact repro steps to make this situation happen. But running tests in the loop will reproduce this issue with high probability:

for i in {1..50}; do make test-memcached; done

I did a small debugging and found that we hang in this loop and if to be more accurate here. If we dig deeper, it turns out that we get stuck here actually.

Please pay attention that #51 may happen because of the same problem.

[ligurio]

But running tests in the loop will reproduce this issue with high probability:

How many times out of 50?

[ylobankov]

But running tests in the loop will reproduce this issue with high probability:

How many times out of 50?

Sorry, I didn't do such measurements.

[ligurio]

Need more details about environment. With script that runs test in loop (for i in {1..50}; do make test-memcached; done), all 50 iterations passed without fails.

sergeyb@pony:~/sources/MRG/memcached$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.3 LTS
Release:        20.04
Codename:       focal
$ tarantool --version
Tarantool 2.10.0-beta1-0-g7da4b1438
Target: Linux-x86_64-RelWithDebInfo
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr -DENABLE_BACKTRACE=ON
Compiler: /usr/bin/cc /usr/lib/ccache/g++
C_FLAGS:-g -O2 -fdebug-prefix-map=/build/tarantool-2.10.0~beta1=. -specs=/usr/share/dpkg/no-pie-compile.specs -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-gnu-alignof-expression -fno-gnu89-inline -Wno-cast-function-type
CXX_FLAGS:-g -O2 -fdebug-prefix-map=/build/tarantool-2.10.0~beta1=. -specs=/usr/share/dpkg/no-pie-compile.specs -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c++11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type
sergeyb@pony:~/sources/MRG/memcached$ 

tarantool-dev 2.10.0~beta1-1 amd64
libevent-dev 2.1.11-stable-1
libsasl2-dev 2.1.27+dfsg-2 amd64

@ylobankov, please assist with repro.

[ylobankov]

Need more details about environment. With script that runs test in loop (for i in {1..50}; do make test-memcached; done), all 50 iterations passed without fails.

sergeyb@pony:~/sources/MRG/memcached$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.3 LTS
Release:        20.04
Codename:       focal
$ tarantool --version
Tarantool 2.10.0-beta1-0-g7da4b1438
Target: Linux-x86_64-RelWithDebInfo
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr -DENABLE_BACKTRACE=ON
Compiler: /usr/bin/cc /usr/lib/ccache/g++
C_FLAGS:-g -O2 -fdebug-prefix-map=/build/tarantool-2.10.0~beta1=. -specs=/usr/share/dpkg/no-pie-compile.specs -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-gnu-alignof-expression -fno-gnu89-inline -Wno-cast-function-type
CXX_FLAGS:-g -O2 -fdebug-prefix-map=/build/tarantool-2.10.0~beta1=. -specs=/usr/share/dpkg/no-pie-compile.specs -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c++11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type
sergeyb@pony:~/sources/MRG/memcached$ 

tarantool-dev 2.10.0~beta1-1 amd64 libevent-dev 2.1.11-stable-1 libsasl2-dev 2.1.27+dfsg-2 amd64

@ylobankov, please assist with repro.

I reproduced this bug on Ubuntu 20.04 quite often. If you still have any issues with that, ping me, I will provide the server.

[ligurio]

How to reproduce the problem:

1. Apply the patch below to test:

--- test/binary/binary-boundary.test.py	2021-12-02 19:09:10.852429691 +0300
+++ test/binary/binary-boundary.py	2021-12-11 10:45:11.327712154 +0300
@@ -4,19 +4,19 @@
 import inspect
 import traceback
 
-saved_path = sys.path[:]
-sys.path.append(os.path.dirname(os.path.abspath(inspect.getsourcefile(lambda:0))))
+root = os.getcwd()
+sys.path.append(os.path.join(root, 'test-run'))
 
 from internal.memcached_connection import MemcachedBinaryConnection
 from internal.memcached_connection import STATUS, COMMANDS
 
-mc = MemcachedBinaryConnection("127.0.0.1", iproto.py_con.port)
+mc = MemcachedBinaryConnection("127.0.0.1", 8080)
 
 def iequal(left, right, level = 1):
     if (left != right):
         tb = traceback.extract_stack()[-(level + 1)]
-        print "Error on line %s:%d: %s not equal %s" % (tb[0], tb[1],
-                repr(left), repr(right))
+        print("Error on line %s:%d: %s not equal %s" % (tb[0], tb[1],
+                repr(left), repr(right)))
         if (isinstance(left, basestring)):
             if (len(left) != len(right)):
                 print("length is different")
@@ -28,28 +28,29 @@
             iequal(res.get('val', val), val, level + 1)
 
 def check(key, flags, val, level = 0):
+    print("Get", key)
     res = mc.get(key)
-    __check(res[0], flags, val, level + 1)
+    #__check(res[0], flags, val, level + 1)
 
 print("""#---------------------# test protocol boundary overruns #---------------------#""")
 
-for i in range(1900, 2100):
+for i in range(1950, 2000):
     print ("iteration %d" % i)
     key  = "test_key_%d" % i
     val  = "x" * i
     mc.setq(key, val, flags=82, nosend=True)
     mc.setq("alt_%s" % key, "blah", flags=82, nosend=True)
-    data = "".join(mc.commands)
+    data = b"".join(mc.commands)
     mc.commands = []
 
     if (len(data) > 2024):
         for j in range(2024, min(2096, len(data))):
+            print("send", data[:j])
             mc.socket.sendall(data[:j])
             time.sleep(0.00001)
+            print("send", data[j:])
             mc.socket.sendall(data[j:])
     else:
         mc.socket.sendall(data)
     check(key, 82, val)
-    check("alt_%s" % key, 82, "blah")
-
-sys.path = saved_path
+    #check("alt_%s" % key, 82, "blah")

2. Create a Tarantool instance file repro.lua with content below:

box.cfg{
    log_level = 7,
    feedback_enabled = false,
    --log = 'tarantool.log',
    --background = true,
    --pid_file = '/home/sergeyb/sources/MRG/memcached/pid',
}
mc = require('memcached')
m = mc.create('instance_1', '8080', {
    expire_enabled = false,
    protocol = 'binary',
    verbosity = 3
})

require('console'):start()

3. Start Tarantool: tarantool repro.lua
4. Run test: python test/binary/binary-boundary.py
5. Test stuck with message: ('Get', 'test_key_1952')

What's going on

• test sends two commands at once (setq and setq):

    mc.setq(key, val, flags=82, nosend=True)                                     
    mc.setq("alt_%s" % key, "blah", flags=82, nosend=True)                       
    data = b"".join(mc.commands)                                                 
    mc.commands = []                                                             
                                                                                 
    if (len(data) > 2024):                                                       
        for j in range(2024, min(2096, len(data))):                              
            print("send", data[:j])                                              
            mc.socket.sendall(data[:j])                                          
            time.sleep(0.00001)                                                  
            print("send", data[j:])                                              
            mc.socket.sendall(data[j:])  

• memcached successfully processed them (check it with command box.space.__mc_instance_1:get('test_key_1952') in Tarantool's console) and reads a request with Getfor key test_key_1952:

2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> tuple_delete(0x7f4a0e00f704)                                                              
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memtx_tuple_delete(0x7f4a0e00f704)                                                        
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop:205                                                                        
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop:210                                                                        
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> ibuf_used 2087, rc 0, batch_count 19                                                      
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop:222                                                                        
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop:176 parse_request                                                          
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop:202                                                                        
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_bin_process
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_bin_process_set
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> SETQ 'test_key_1952' '<DATA>'
375731712, expire - 0                                                                                                                                         
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> opaque - 7, cas - 0
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memtx_tuple_new(1992) = 0x7f4a0e0c2428
2021-12-13 14:55:08.799 [568488] main D> cpipe_flush_cb: locking &endpoint->mutex
2021-12-13 14:55:08.799 [568488] main D> cpipe_flush_cb: unlocking &endpoint->mutex
2021-12-13 14:55:08.799 [568488] wal/101/main D> cbus_endpoint_fetch: locking &endpoint->mutex
2021-12-13 14:55:08.799 [568488] wal/101/main D> cbus_endpoint_fetch: unlocking &endpoint->mutex
2021-12-13 14:55:08.799 [568488] wal D> cpipe_flush_cb: locking &endpoint->mutex
2021-12-13 14:55:08.799 [568488] wal D> cpipe_flush_cb: unlocking &endpoint->mutex
2021-12-13 14:55:08.799 [568488] main D> cbus_endpoint_fetch: locking &endpoint->mutex
2021-12-13 14:55:08.799 [568488] main D> cbus_endpoint_fetch: unlocking &endpoint->mutex
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> tuple_delete(0x7f4a0e0c141c)
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D>memtx_tuple_delete(0x7f4a0e0c141c)
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memtx_tuple_delete(0x7f4a0e0c141c)
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop:205
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop:210
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> ibuf_used 90, rc 0, batch_count 20
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> ibuf_used 90
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop: 230 memcached_flush
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop:232
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> memcached_loop_read to_read 1
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> mnet_read_ahead() start
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> mnet_read_ahead: nrd -1
2021-12-13 14:55:08.799 [568488] main/113/server/127.0.0.1:36442 D> mnet_read_ahead: coio_wait begin

• batch_count is set to 20 by default, and on condition below we go out of if..then..else and go to next memcached_loop_read() at the beginning of the loop, see internal/memcached.c:

		} else if (rc == 0 && ibuf_used(con->in) > 0 &&
			   batch_count < con->cfg->batch_count) {
			batch_count++;
			goto next;
		}