test: flaky vinyl/deferred_delete.test.lua #5089
Description
Tarantool version:
Tarantool 2.5.0-146-ga9276dae0
Target: Linux-x86_64-RelWithDebInfo
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=ON
Compiler: /usr/bin/cc /usr/bin/c++
C_FLAGS: -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 -Werror
CXX_FLAGS: -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 -Werror
OS version:
Linux
Bug description:
[044] --- vinyl/deferred_delete.result Fri Jun 5 06:49:36 2020
[044] +++ vinyl/deferred_delete.reject Thu Jun 18 02:09:25 2020
[044] @@ -702,7 +702,7 @@
[044] ...
[044] box.snapshot()
[044] ---
[044] -- ok
[044] +- error: Failed to write to disk
[044] ...
[044] -- Generate deferred DELETEs.
[044] pk:compact()
[044]
[044] Last 15 lines of Tarantool Log file [Instance "vinyl"][/builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl.log]:
[044] 2020-06-18 02:09:05.982 [30632] main/108/vinyl.scheduler I> 520/0: dump completed
[044] 2020-06-18 02:09:05.982 [30632] main/108/vinyl.scheduler I> dumped 98543 bytes in 1.4 s, rate 0.1 MB/s
[044] 2020-06-18 02:09:05.982 [30632] main/121/console/unix/: I> vinyl checkpoint completed
[044] 2020-06-18 02:09:06.586 [30632] main I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/00000000000000002571.snap
[044] 2020-06-18 02:09:06.586 [30632] main I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/00000000000000002568.vylog
[044] 2020-06-18 02:09:06.586 [30632] main/105/gc I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/518/0/00000000000000000213.index
[044] 2020-06-18 02:09:06.586 [30632] main/105/gc I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/518/0/00000000000000000213.run
[044] 2020-06-18 02:09:06.587 [30632] main/105/gc I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/518/1/00000000000000000219.index
[044] 2020-06-18 02:09:06.587 [30632] main/105/gc I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/518/1/00000000000000000219.run
[044] 2020-06-18 02:09:06.587 [30632] main/105/gc I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/518/1/00000000000000000214.index
[044] 2020-06-18 02:09:06.587 [30632] main/105/gc I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/518/1/00000000000000000214.run
[044] 2020-06-18 02:09:06.587 [30632] main/105/gc I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/518/1/00000000000000000217.index
[044] 2020-06-18 02:09:06.587 [30632] main/105/gc I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/518/1/00000000000000000217.run
[044] 2020-06-18 02:09:06.587 [30632] wal I> removed /builds/WHBm2_Sk/0/tarantool/tarantool/test/var/044_vinyl/vinyl/00000000000000002571.xlog
[044] 2020-06-18 02:09:06.590 [30632] main/121/console/unix/: I> set 'vinyl_cache' configuration option to 10240
The same as #4979
- https://gitlab.com/tarantool/tarantool/-/jobs/610462469#L6715
checksum f56467141ef34c20c16ef86ca4124c47
[082] --- vinyl/deferred_delete.result Thu Jun 11 12:07:39 2020
[082] +++ vinyl/deferred_delete.reject Wed Jun 24 23:22:01 2020
[082] @@ -207,11 +207,11 @@
[082] ...
[082] i1:stat().rows -- 10 old REPLACE + 5 new REPLACEs + 10 deferred DELETEs
[082] ---
[082] -- 25
[082] +- 35
[082] ...
[082] i2:stat().rows -- ditto
[082] ---
[082] -- 25
[082] +- 35
[082] ...
[082] -- Deferred DELETEs must be ignored by the read iterator, because
[082] -- they may break the read iterator invariant, so they don't reduce
[082]
[082] Last 15 lines of Tarantool Log file [Instance "vinyl"][/tarantool/test/var/082_vinyl/vinyl.log]:
[082] 2020-06-24 23:21:54.559 [9416] main/108/vinyl.scheduler I> 524/0: dump completed
[082] 2020-06-24 23:21:54.559 [9416] main/108/vinyl.scheduler I> dumped 98543 bytes in 0.6 s, rate 0.2 MB/s
[082] 2020-06-24 23:21:54.559 [9416] main/121/console/unix/: I> vinyl checkpoint completed
[082] 2020-06-24 23:21:54.829 [9416] main I> removed /tarantool/test/var/082_vinyl/vinyl/00000000000000008244.snap
[082] 2020-06-24 23:21:54.829 [9416] main I> removed /tarantool/test/var/082_vinyl/vinyl/00000000000000008243.vylog
[082] 2020-06-24 23:21:54.829 [9416] main/105/gc I> removed /tarantool/test/var/082_vinyl/vinyl/522/0/00000000000000000315.index
[082] 2020-06-24 23:21:54.830 [9416] main/105/gc I> removed /tarantool/test/var/082_vinyl/vinyl/522/0/00000000000000000315.run
[082] 2020-06-24 23:21:54.830 [9416] main/105/gc I> removed /tarantool/test/var/082_vinyl/vinyl/522/1/00000000000000000319.index
[082] 2020-06-24 23:21:54.830 [9416] main/105/gc I> removed /tarantool/test/var/082_vinyl/vinyl/522/1/00000000000000000319.run
[082] 2020-06-24 23:21:54.831 [9416] main/105/gc I> removed /tarantool/test/var/082_vinyl/vinyl/522/1/00000000000000000312.index
[082] 2020-06-24 23:21:54.831 [9416] main/105/gc I> removed /tarantool/test/var/082_vinyl/vinyl/522/1/00000000000000000312.run
[082] 2020-06-24 23:21:54.831 [9416] main/105/gc I> removed /tarantool/test/var/082_vinyl/vinyl/522/1/00000000000000000316.index
[082] 2020-06-24 23:21:54.832 [9416] main/105/gc I> removed /tarantool/test/var/082_vinyl/vinyl/522/1/00000000000000000316.run
[082] 2020-06-24 23:21:54.832 [9416] wal I> removed /tarantool/test/var/082_vinyl/vinyl/00000000000000008244.xlog
[082] 2020-06-24 23:21:54.836 [9416] main/121/console/unix/: I> set 'vinyl_cache' configuration option to 10240
- test broke test-run:
[006] vinyl/deferred_delete.test.lua
[006] [Instance "vinyl"] Tarantool server failed to start
[006]
[006] Last 15 lines of Tarantool Log file [Instance "vinyl"][/home/ubuntu/tarantool/test/var/006_vinyl/vinyl.log]:
[006] 2021-06-04 08:53:09.266 [1179373] main/103/vinyl C> Tarantool 2.9.0-57-gea0b126ff
[006] 2021-06-04 08:53:09.266 [1179373] main/103/vinyl C> log level 5
[006] 2021-06-04 08:53:09.266 [1179373] main/103/vinyl I> wal/engine cleanup is paused
[006] 2021-06-04 08:53:09.267 [1179373] main/103/vinyl I> mapping 536870912 bytes for memtx tuple arena...
[006] 2021-06-04 08:53:09.267 [1179373] main/103/vinyl I> Actual slab_alloc_factor calculated on the basis of desired slab_alloc_factor = 1.044274
[006] 2021-06-04 08:53:09.267 [1179373] main/103/vinyl I> mapping 536870912 bytes for vinyl tuple arena...
[006] 2021-06-04 08:53:09.287 [1179373] main/103/vinyl I> instance uuid dc34dfe1-bbc9-418b-a013-5c02090b4ec1
[006] 2021-06-04 08:53:09.287 [1179373] main/103/vinyl I> instance vclock {0: 10, 1: 27740}
[006] 2021-06-04 08:53:09.289 [1179373] main/103/vinyl I> : bound to unix/:(socket)
[006] 2021-06-04 08:53:09.292 [1179373] coio vy_log.c:2276 E> failed to process vylog record: delete_slice{slice_id=649, }
[006] 2021-06-04 08:53:09.292 [1179373] main/103/vinyl vy_log.c:2141 E> ER_INVALID_VYLOG_FILE: Invalid VYLOG file: Slice 649 deleted but not registered
[006] 2021-06-04 08:53:09.292 [1179373] main/103/vinyl vy_log.c:2495 E> failed to load `/home/ubuntu/tarantool/test/var/006_vinyl/vinyl/00000000000000027217.vylog'
[006] 2021-06-04 08:53:09.292 [1179373] main/103/vinyl vy_log.c:2141 E> ER_INVALID_VYLOG_FILE: Invalid VYLOG file: Slice 649 deleted but not registered
[006] 2021-06-04 08:53:09.292 [1179373] main/103/vinyl F> can't initialize storage: Invalid VYLOG file: Slice 649 deleted but not registered
[006] 2021-06-04 08:53:09.292 [1179373] main/103/vinyl F> can't initialize storage: Invalid VYLOG file: Slice 649 deleted but not registered
[006]
[006] Worker "006_vinyl" received the following error; stopping...
[006] Traceback (most recent call last):
[006] File "/home/ubuntu/tarantool/test-run/lib/worker.py", line 320, in run_task
[006] short_status, result_checksum, duration = self.suite.run_test(
[006] File "/home/ubuntu/tarantool/test-run/lib/test_suite.py", line 274, in run_test
[006] short_status, result_checksum = test.run(server)
[006] File "/home/ubuntu/tarantool/test-run/lib/test.py", line 190, in run
[006] self.execute(server)
[006] File "/home/ubuntu/tarantool/test-run/lib/tarantool_server.py", line 399, in execute
[006] ts.stop_nondefault(signal=signal.SIGKILL)
[006] File "/home/ubuntu/tarantool/test-run/lib/preprocessor.py", line 443, in stop_nondefault
[006] v.stop(silent=True, signal=signal)
[006] File "/home/ubuntu/tarantool/test-run/lib/tarantool_server.py", line 1069, in stop
[006] save_join(self.crash_detector)
[006] File "/home/ubuntu/tarantool/test-run/lib/tarantool_server.py", line 56, in save_join
[006] green_obj.get(timeout=timeout)
[006] File "src/gevent/greenlet.py", line 824, in gevent._gevent_cgreenlet.Greenlet.get
[006] File "src/gevent/greenlet.py", line 812, in gevent._gevent_cgreenlet.Greenlet.get
[006] File "src/gevent/_greenlet_primitives.py", line 61, in gevent._gevent_c_greenlet_primitives.SwitchOutGreenletWithLoop.switch
[006] File "src/gevent/_greenlet_primitives.py", line 61, in gevent._gevent_c_greenlet_primitives.SwitchOutGreenletWithLoop.switch
[006] File "src/gevent/_greenlet_primitives.py", line 65, in gevent._gevent_c_greenlet_primitives.SwitchOutGreenletWithLoop.switch
[006] File "src/gevent/_gevent_c_greenlet_primitives.pxd", line 35, in gevent._gevent_c_greenlet_primitives._greenlet_switch
[006] File "src/gevent/greenlet.py", line 906, in gevent._gevent_cgreenlet.Greenlet.run
[006] File "/home/ubuntu/.local/lib/python3.8/site-packages/gevent/baseserver.py", line 34, in _handle_and_close_when_done
[006] return handle(*args_tuple)
[006] File "/home/ubuntu/tarantool/test-run/lib/inspector.py", line 103, in handle
[006] result = self.parser.parse_preprocessor(line)
[006] File "/home/ubuntu/tarantool/test-run/lib/preprocessor.py", line 123, in parse_preprocessor
[006] return self.server(stype, sname, options)
[006] File "/home/ubuntu/tarantool/test-run/lib/preprocessor.py", line 349, in server
[006] return getattr(self, attr)(ctype, sname, opts)
[006] File "/home/ubuntu/tarantool/test-run/lib/preprocessor.py", line 340, in server_restart
[006] self.server_start(ctype, sname, opts)
[006] File "/home/ubuntu/tarantool/test-run/lib/preprocessor.py", line 209, in server_start
[006] self.servers[sname].start(silent=True, rais=True, wait=wait,
[006] File "/home/ubuntu/tarantool/test-run/lib/tarantool_server.py", line 891, in start
[006] self.wait_until_started(wait_load)
[006] File "/home/ubuntu/tarantool/test-run/lib/tarantool_server.py", line 1116, in wait_until_started
[006] self.logfile_pos.seek_wait(msg, p, self.name)
[006] File "/home/ubuntu/tarantool/test-run/lib/tarantool_server.py", line 469, in seek_wait
[006] raise TarantoolStartError(name)
[006] lib.tarantool_server.TarantoolStartError
[006]
[006] Exception:
Steps to reproduce:
Optional (but very desirable):
- coredump
- backtrace
- netstat