[Tarantool-patches] [PATCH] test: use grep_log in tests

[Tarantool-patches] [PATCH] test: use grep_log in tests

[Olga Arkhangelskaia]

Refactoring: replace grep_for_broken_lsn with grep_log from test_run.
---
 test/xlog/panic_on_broken_lsn.result   | 50 +++++++++-----------------
 test/xlog/panic_on_broken_lsn.test.lua | 29 ++++-----------
 2 files changed, 22 insertions(+), 57 deletions(-)

diff --git a/test/xlog/panic_on_broken_lsn.result b/test/xlog/panic_on_broken_lsn.result
index 1e62680eb..15b229c76 100644
--- a/test/xlog/panic_on_broken_lsn.result
+++ b/test/xlog/panic_on_broken_lsn.result
@@ -12,36 +12,6 @@ test_run:cleanup_cluster()
 fio = require('fio')
 ---
 ...
-test_run:cmd("setopt delimiter ';'")
----
-- true
-...
-function grep_file_tail(filepath, bytes, pattern)
-    local fh = fio.open(filepath, {'O_RDONLY'})
-    local size = fh:seek(0, 'SEEK_END')
-    if size < bytes then
-        bytes = size
-    end
-    fh:seek(-bytes, 'SEEK_END')
-    local line = fh:read(bytes)
-    fh:close()
-    return string.match(line, pattern)
-end;
----
-...
-function grep_broken_lsn(logpath, lsn)
-    local msg = grep_file_tail(logpath, 256,
-        string.format("LSN for 1 is used twice or COMMIT order is broken: " ..
-                      "confirmed: %d, new: %d, req: ({.*})", lsn, lsn))
-    msg = string.gsub(msg, string.format('lsn: %d, ', lsn), '')
-    return msg
-end;
----
-...
-test_run:cmd("setopt delimiter ''");
----
-- true
-...
 -- Testing case of panic on recovery
 test_run:cmd('create server panic with script="xlog/panic.lua"')
 ---
@@ -97,9 +67,15 @@ test_run:cmd('start server panic with crash_expected=True')
 - false
 ...
 -- Check that log contains the mention of broken LSN and the request printout
-grep_broken_lsn(fio.pathjoin(fio.cwd(), 'panic.log'), 1)
+path = fio.pathjoin(fio.cwd(), 'panic.log')
+---
+...
+str = "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1"
 ---
-- '{type: ''REPLACE'', replica_id: 1, space_id: 272, index_id: 0, tuple: ["t0", "v1"]}'
+...
+test_run:grep_log(nil, str, nil, {path = path})~= nil
+---
+- true
 ...
 test_run:cmd('cleanup server panic')
 ---
@@ -164,9 +140,15 @@ box.error.injection.set("ERRINJ_RELAY_BREAK_LSN", -1)
 - ok
 ...
 -- Check that log contains the mention of broken LSN and the request printout
-grep_broken_lsn(fio.pathjoin(fio.cwd(), 'replica.log'), lsn)
+path = fio.pathjoin(fio.cwd(), 'replica.log')
 ---
-- '{type: ''INSERT'', replica_id: 1, space_id: 9000, index_id: 0, tuple: [2, "v1"]}'
+...
+str = string.format("LSN for 1 is used twice or COMMIT order is broken: confirmed: %d, new: %d", lsn, lsn)
+---
+...
+test_run:grep_log(nil, str, nil, {path = path}) ~= nil
+---
+- true
 ...
 test_run:cmd('cleanup server replica')
 ---
diff --git a/test/xlog/panic_on_broken_lsn.test.lua b/test/xlog/panic_on_broken_lsn.test.lua
index 80cccd918..002223ac9 100644
--- a/test/xlog/panic_on_broken_lsn.test.lua
+++ b/test/xlog/panic_on_broken_lsn.test.lua
@@ -5,26 +5,6 @@ test_run = env.new()
 test_run:cleanup_cluster()
 
 fio = require('fio')
-test_run:cmd("setopt delimiter ';'")
-function grep_file_tail(filepath, bytes, pattern)
-    local fh = fio.open(filepath, {'O_RDONLY'})
-    local size = fh:seek(0, 'SEEK_END')
-    if size < bytes then
-        bytes = size
-    end
-    fh:seek(-bytes, 'SEEK_END')
-    local line = fh:read(bytes)
-    fh:close()
-    return string.match(line, pattern)
-end;
-function grep_broken_lsn(logpath, lsn)
-    local msg = grep_file_tail(logpath, 256,
-        string.format("LSN for 1 is used twice or COMMIT order is broken: " ..
-                      "confirmed: %d, new: %d, req: ({.*})", lsn, lsn))
-    msg = string.gsub(msg, string.format('lsn: %d, ', lsn), '')
-    return msg
-end;
-test_run:cmd("setopt delimiter ''");
 
 -- Testing case of panic on recovery
 test_run:cmd('create server panic with script="xlog/panic.lua"')
@@ -47,8 +27,9 @@ fio.unlink(xlogs[#xlogs])
 test_run:cmd('start server panic with crash_expected=True')
 
 -- Check that log contains the mention of broken LSN and the request printout
-grep_broken_lsn(fio.pathjoin(fio.cwd(), 'panic.log'), 1)
-
+path = fio.pathjoin(fio.cwd(), 'panic.log')
+str = "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1"
+test_run:grep_log(nil, str, nil, {path = path})~= nil
 test_run:cmd('cleanup server panic')
 test_run:cmd('delete server panic')
 
@@ -78,7 +59,9 @@ test_run:cmd('start server replica with crash_expected=True')
 box.error.injection.set("ERRINJ_RELAY_BREAK_LSN", -1)
 
 -- Check that log contains the mention of broken LSN and the request printout
-grep_broken_lsn(fio.pathjoin(fio.cwd(), 'replica.log'), lsn)
+path = fio.pathjoin(fio.cwd(), 'replica.log')
+str = string.format("LSN for 1 is used twice or COMMIT order is broken: confirmed: %d, new: %d", lsn, lsn)
+test_run:grep_log(nil, str, nil, {path = path}) ~= nil
 
 test_run:cmd('cleanup server replica')
 test_run:cmd('delete server replica')
-- 
2.20.1 (Apple Git-117)

Re: [Tarantool-patches] [PATCH] test: use grep_log in tests

[Alexander Turenko]

I like the simplification of the test you made. Please, consider several
comments below.

Please, see test-run patch comments first (see [1]), because I proposed
to rename the option from `path` to `filename`.

[1]: https://lists.tarantool.org/pipermail/tarantool-patches/2020-March/014638.html

WBR, Alexander Turenko.

> test: use grep_log in tests

Nit: I would make the commit header a bit more certain and point the
test name right here.

>
> Refactoring: replace grep_for_broken_lsn with grep_log from test_run.
> ---
>  test/xlog/panic_on_broken_lsn.result   | 50 +++++++++-----------------
>  test/xlog/panic_on_broken_lsn.test.lua | 29 ++++-----------
>  2 files changed, 22 insertions(+), 57 deletions(-)

>  -- Check that log contains the mention of broken LSN and the request printout
> -grep_broken_lsn(fio.pathjoin(fio.cwd(), 'panic.log'), 1)
> +path = fio.pathjoin(fio.cwd(), 'panic.log')
> +---
> +...
> +str = "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1"
>  ---
> -- '{type: ''REPLACE'', replica_id: 1, space_id: 272, index_id: 0, tuple: ["t0", "v1"]}'
> +...

I would keep the request information as proof that we found the log
entry generated by the errinj above and not something else. May be
implemented like so:

 | path = fio.pathjoin(fio.cwd(), 'replica.log')
 | str = string.format("LSN for 1 is used twice or COMMIT order is broken: confirmed: %d, new: %d, req: .*", lsn, lsn)
 | found = test_run:grep_log(nil, str, 256, {path = path})
 | (found:gsub('^.*, req: ', ''):gsub('lsn: %d+', 'lsn: <lsn>'))

(See below re 256.)

(Parenthesis are to discard the second return value of string.gsub().)

>  -- Check that log contains the mention of broken LSN and the request printout
> -grep_broken_lsn(fio.pathjoin(fio.cwd(), 'panic.log'), 1)
> -
> +path = fio.pathjoin(fio.cwd(), 'panic.log')
> +str = "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1"
> +test_run:grep_log(nil, str, nil, {path = path})~= nil

Nit: spaces are needed around '~='.

I would keep 265 bytes window (there is `bytes` option in grep_log()).
Lesser value is more safe: if the expected log entry is not appear we
can occasionally found the entry from another test if the window is big
enough for this. It means that the test may pass even when is should
not. So it is good to keep the window small.

Re: [Tarantool-patches] [PATCH] test: use grep_log in tests

[Olga Arkhangelskaia]

Hi, Alexander!

I have fixed things you have pointed out and pushed it to branch

https://github.com/tarantool/tarantool/tree/OKriw/refactoring_of_panic_on_broken_lsn.test.lua

The branch can not be tested without

https://github.com/tarantool/test-run/tree/OKriw/gh-196-Extend-grep_log-for-crashed-instances

04.03.2020 18:31, Alexander Turenko пишет:
> I like the simplification of the test you made. Please, consider several
> comments below.
>
> Please, see test-run patch comments first (see [1]), because I proposed
> to rename the option from `path` to `filename`.
>
> [1]: https://lists.tarantool.org/pipermail/tarantool-patches/2020-March/014638.html
>
> WBR, Alexander Turenko.
>
>> test: use grep_log in tests

[PATCH] tests: use grep_log opt.filename in panic_on_broken_lsn

Now we use filename option from grep_log instead of custom log
search.

> Nit: I would make the commit header a bit more certain and point the
> test name right here.
>
>> Refactoring: replace grep_for_broken_lsn with grep_log from test_run.
>> ---
>>   test/xlog/panic_on_broken_lsn.result   | 50 +++++++++-----------------
>>   test/xlog/panic_on_broken_lsn.test.lua | 29 ++++-----------
>>   2 files changed, 22 insertions(+), 57 deletions(-)
>>   -- Check that log contains the mention of broken LSN and the request printout
>> -grep_broken_lsn(fio.pathjoin(fio.cwd(), 'panic.log'), 1)
>> +path = fio.pathjoin(fio.cwd(), 'panic.log')
>> +---
>> +...
>> +str = "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1"
>>   ---
>> -- '{type: ''REPLACE'', replica_id: 1, space_id: 272, index_id: 0, tuple: ["t0", "v1"]}'
>> +...
> I would keep the request information as proof that we found the log
> entry generated by the errinj above and not something else. May be
> implemented like so:
>
>   | path = fio.pathjoin(fio.cwd(), 'replica.log')
>   | str = string.format("LSN for 1 is used twice or COMMIT order is broken: confirmed: %d, new: %d, req: .*", lsn, lsn)
>   | found = test_run:grep_log(nil, str, 256, {path = path})
>   | (found:gsub('^.*, req: ', ''):gsub('lsn: %d+', 'lsn: <lsn>'))
>
> (See below re 256.)
>
> (Parenthesis are to discard the second return value of string.gsub().)

+filename = fio.pathjoin(fio.cwd(), 'panic.log')
+str = string.format("LSN for 1 is used twice or COMMIT order is broken: 
confirmed: 1, new: 1, req: .*")
+found = test_run:grep_log(nil, str, 256, {filename = filename})
+(found:gsub('^.*, req: ', ''):gsub('lsn: %d+', 'lsn: <lsn>'))


+filename = fio.pathjoin(fio.cwd(), 'replica.log')
+str = string.format("LSN for 1 is used twice or COMMIT order is broken: 
confirmed: %d, new: %d, req: .*", lsn, lsn)
+found = test_run:grep_log(nil, str, 256, {filename = filename})
+(found:gsub('^.*, req: ', ''):gsub('lsn: %d+', 'lsn: <lsn>'))

>>   -- Check that log contains the mention of broken LSN and the request printout
>> -grep_broken_lsn(fio.pathjoin(fio.cwd(), 'panic.log'), 1)
>> -
>> +path = fio.pathjoin(fio.cwd(), 'panic.log')
>> +str = "LSN for 1 is used twice or COMMIT order is broken: confirmed: 1, new: 1"
>> +test_run:grep_log(nil, str, nil, {path = path})~= nil
> Nit: spaces are needed around '~='.
>
> I would keep 265 bytes window (there is `bytes` option in grep_log()).
> Lesser value is more safe: if the expected log entry is not appear we
> can occasionally found the entry from another test if the window is big
> enough for this. It means that the test may pass even when is should
> not. So it is good to keep the window small.

Re: [Tarantool-patches] [PATCH] test: use grep_log in tests

[Alexander Turenko]

On Tue, Mar 10, 2020 at 02:35:09PM +0300, Olga Arkhangelskaia wrote:
> Hi, Alexander!
> 
> I have fixed things you have pointed out and pushed it to branch
> 
> https://github.com/tarantool/tarantool/tree/OKriw/refactoring_of_panic_on_broken_lsn.test.lua

Pushed to master, 2.3, 2.2 and 1.10.

Found https://github.com/tarantool/tarantool/issues/4806 while testing
the change before push (looks unrelated to the change, so pushed
anyway).

CCed Kirill.

> 
> The branch can not be tested without
> 
> https://github.com/tarantool/test-run/tree/OKriw/gh-196-Extend-grep_log-for-crashed-instances

test-run part was pushed in
https://lists.tarantool.org/pipermail/tarantool-patches/2020-March/014786.html

> > > test: use grep_log in tests
> >
> > Nit: I would make the commit header a bit more certain and point the
> > test name right here.
> 
> [PATCH] tests: use grep_log opt.filename in panic_on_broken_lsn

A bit changed: used 'test' prefix, removed 'opt'.