From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 870AA27DFA for ; Sat, 20 Oct 2018 14:36:04 -0400 (EDT) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing.freelists.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id tMvdzPrPrTQH for ; Sat, 20 Oct 2018 14:36:04 -0400 (EDT) Received: from smtpng2.m.smailru.net (smtpng2.m.smailru.net [94.100.179.3]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTPS id A1D7B27DE7 for ; Sat, 20 Oct 2018 14:36:03 -0400 (EDT) Date: Sat, 20 Oct 2018 21:36:01 +0300 From: Alexander Turenko Subject: [tarantool-patches] Re: [PATCH] lua: show locals when a tap test fails Message-ID: <20181020183601.laor3saek7jxtfvp@tkn_work_nb> References: <84509c8ab6e29159082ff27a5d72c9228adc1c21.1534595542.git.alexander.turenko@tarantool.org> <4ed59be1-1b73-423f-f016-d7ecb14ed907@tarantool.org> <20180923175917.fehrr36hxfthqgvw@tkn_work_nb> <2034b653-1054-470d-1296-d2d74f990a7b@tarantool.org> <20180927004516.uivnneuomck3nls5@tkn_work_nb> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline In-Reply-To: <20180927004516.uivnneuomck3nls5@tkn_work_nb> Sender: tarantool-patches-bounce@freelists.org Errors-to: tarantool-patches-bounce@freelists.org Reply-To: tarantool-patches@freelists.org List-help: List-unsubscribe: List-software: Ecartis version 1.0.0 List-Id: tarantool-patches List-subscribe: List-owner: List-post: List-archive: To: Vladislav Shpilevoy Cc: Eugine Blikh , tarantool-patches@freelists.org, Kirill Yukhin On Thu, Sep 27, 2018 at 03:45:16AM +0300, Alexander Turenko wrote: > On Mon, Sep 24, 2018 at 01:47:45PM +0300, Vladislav Shpilevoy wrote: > > Hi! Thanks for the fixes! > > > > > > > @@ -245,7 +280,7 @@ local function check(test) > > > > > if test.planned ~= test.total then > > > > > if test.parent ~= nil then > > > > > ok(test.parent, false, "bad plan", { planned = test.planned; > > > > > - run = test.total}) > > > > > + run = test.total}, {locals = false}) > > > > > > > > 6. Are we sure, that locals should be printed by default? Maybe > > > > it would be better to print them on demand only via a global > > > > option and remove per-test-case option? As I imagine a typical > > > > test fail, when a test did not pass, you turn locals printing > > > > on and run the test again. > > > > > > > > > > The primary reason of the option is to omit the second run. It is more > > > useful when the fail is flaky or when it occurs in CI. If you going to > > > do second run you can print anything you want manually. > > > > > > So I think it worth to enable it by default or discard the patch > > > entirely. Or maybe control it from an environment variable. > > > > > > I personally use the patch around month locally. It sometimes gives very > > > large output (graphql schemas), but saves time to write something like > > > `print(require('yaml').encode(res))` each time a test fails. > > > > > > If you dislike such extra output for failing tests, we should skip the > > > patch entirely. It is useful or not useful, not something in the middle. > > > > Understandable. Then LGTM, looks useful. > > > > To be honest, now I don't so sure in the thought that we should enable > it by default or discard completely. Sometimes it is useful to have > clean picture which cases are passed and which are not w/o extra > information (w/o locals and w/o traces). But sometimes it is useful to > know exact reason of a certain fail and have as much info as possible > (so locals are helpful). > > When work on a patch locally both situations occur. Don't sure about CI. > > Now I thinking about the following implementation: save locals for a > first failing case, print it after the whole test in the uppermost > test:check() and then print cases list (with ok/not ok, name and so on) > again to bring it to the focus. It gives both benefits: a developer does > not have to scroll for pass/fail list and have detailed info available > after some scrolling. > > We could simplify that to 'print traces and locals during the test, then > give a short list in the uppermost test:check()', but there is a > pitfall. When something (say, a test case preparation) lead to premature > exit (say, because of a raised error) we still want to see the whole > picture (what is passed and what is failed) at the first glance and > then, maybe, detailed information about the fail. With the proposed > implementation we'll get the cases list, but not details: I think it is > better then vice versa. > > So, to sum it up, I propose to keep a during-test output short, then, if > the test reach the uppermost test:check(), give details and repeat the > short cases list. > > Now I think how better to handle the raised error case. Maybe it worth > to do xpcall around the whole test and then traverse over a stack to > find a frame with the uppermost test and print locals for that frame. > I'm thinking whether it is implementable w/o extra handle from a test > writer, say, as a global option (_G.print_test_locals_before_exit) of > tarantool that can be set by test-run. > > Ugh, tricky thing... > > WBR, Alexander Turenko. I retained myself from implementing the complex and unobvious behaviour. Now it is disabled by default. Rebased on top of 2.1. The diff from the previous version and the full diff are below. https://github.com/tarantool/tarantool/issues/3627 https://github.com/tarantool/tarantool/tree/Totktonada/gh-3627-tap-show-local-variables https://travis-ci.org/tarantool/tarantool/builds/444149450 WBR, Alexander Turenko. Diff from the previous version ------------------------------ diff --git a/src/lua/tap.lua b/src/lua/tap.lua index 5074305d3..d0f8b08c6 100644 --- a/src/lua/tap.lua +++ b/src/lua/tap.lua @@ -69,7 +69,7 @@ local function ok(test, cond, message, extra, opts) elseif test.locals ~= nil then show_locals = test.locals else - show_locals = true + show_locals = false end test.total = test.total + 1 io.write(string.rep(' ', 4 * test.level)) @@ -257,7 +257,7 @@ local function test(parent, name, fun, ...) failed = 0; planned = 0; trace = parent == nil or parent.trace; - locals = parent == nil or parent.locals; + locals = parent ~= nil and parent.locals; }, test_mt) if fun ~= nil then test:diag('%s', test.name) @@ -281,6 +281,7 @@ local function check(test) test.checked = true if test.planned ~= test.total then if test.parent ~= nil then + -- Do not show locals with the 'bad plan' message. ok(test.parent, false, "bad plan", { planned = test.planned; run = test.total}, {locals = false}) else @@ -289,6 +290,8 @@ local function check(test) end elseif test.failed > 0 then if test.parent ~= nil then + -- Do not show locals with the 'failed subtests' + -- message. ok(test.parent, false, "failed subtests", { failed = test.failed; planned = test.planned; @@ -298,7 +301,7 @@ local function check(test) end else if test.parent ~= nil then - ok(test.parent, true, test.name, {locals = false}) + ok(test.parent, true, test.name) end end return test.planned == test.total and test.failed == 0 diff --git a/test/app-tap/tap.test.lua b/test/app-tap/tap.test.lua index 29dc0b100..a810be3f6 100755 --- a/test/app-tap/tap.test.lua +++ b/test/app-tap/tap.test.lua @@ -12,10 +12,9 @@ local tap = require "tap" -- Create a root test -- test = tap.test("root test") --- Disable stack traces and locals for this test because Tarantool test system --- also checks test output. +-- Disable stack traces for this test because Tarantool test system also +-- checks test output. test.trace = false -test.locals = false -- -- ok, fail and skip predicates Full diff --------- diff --git a/src/lua/tap.lua b/src/lua/tap.lua index 546d15392..d0f8b08c6 100644 --- a/src/lua/tap.lua +++ b/src/lua/tap.lua @@ -1,6 +1,6 @@ --- tap.lua internal file --- ---- The Test Anything Protocol vesion 13 producer +--- The Test Anything Protocol version 13 producer --- -- yaml formatter must be able to encode any Lua variable @@ -36,12 +36,41 @@ local function traceback(level) return trace end +local function locals(test, level) + level = level or 3 + local variables = {} + local idx = 1 + while true do + local name, value = debug.getlocal(level, idx) + if not name then + return variables + end + -- Compare a table with a tuple raises an error, so we + -- check types first. + local is_test = type(value) == type(test) and value == test + -- Temporary values start with '('. + if not name:startswith('(') and not is_test then + variables[name] = value + end + idx = idx + 1 + end +end + local function diag(test, fmt, ...) io.write(string.rep(' ', 4 * test.level), "# ", string.format(fmt, ...), "\n") end -local function ok(test, cond, message, extra) +local function ok(test, cond, message, extra, opts) + opts = opts or {} + local show_locals + if opts.locals ~= nil then + show_locals = opts.locals + elseif test.locals ~= nil then + show_locals = test.locals + else + show_locals = false + end test.total = test.total + 1 io.write(string.rep(' ', 4 * test.level)) if cond then @@ -58,6 +87,9 @@ local function ok(test, cond, message, extra) extra.filename = extra.trace[#extra.trace].filename extra.line = extra.trace[#extra.trace].line end + if show_locals then + extra.locals = locals(test) + end if next(extra) == nil then return false -- don't have extra information end @@ -224,7 +256,8 @@ local function test(parent, name, fun, ...) total = 0; failed = 0; planned = 0; - trace = parent == nil and true or parent.trace; + trace = parent == nil or parent.trace; + locals = parent ~= nil and parent.locals; }, test_mt) if fun ~= nil then test:diag('%s', test.name) @@ -248,18 +281,21 @@ local function check(test) test.checked = true if test.planned ~= test.total then if test.parent ~= nil then + -- Do not show locals with the 'bad plan' message. ok(test.parent, false, "bad plan", { planned = test.planned; - run = test.total}) + run = test.total}, {locals = false}) else diag(test, string.format("bad plan: planned %d run %d", test.planned, test.total)) end elseif test.failed > 0 then if test.parent ~= nil then + -- Do not show locals with the 'failed subtests' + -- message. ok(test.parent, false, "failed subtests", { failed = test.failed; planned = test.planned; - }) + }, {locals = false}) else diag(test, "failed subtest: %d", test.failed) end diff --git a/test/app-tap/tap.result b/test/app-tap/tap.result index 3e7882331..ea6160191 100644 --- a/test/app-tap/tap.result +++ b/test/app-tap/tap.result @@ -1,5 +1,5 @@ TAP version 13 -1..32 +1..33 ok - true ok - extra information is not printed on success not ok - extra printed using yaml only on failure @@ -148,4 +148,27 @@ not ok - failed subtests ok - unlike(abcde, acd) # like: end ok - like -# failed subtest: 15 + # locals + 1..1 + # locals nested + 1..2 + ok - locals are not printed in case of success + not ok - locals are printed in case of fail + --- + locals: + a: 42 + tuple: [] + ... + # locals nested: end + not ok - failed subtests + --- + planned: 2 + failed: 1 + ... + # locals: end +not ok - failed subtests + --- + planned: 1 + failed: 1 + ... +# failed subtest: 16 diff --git a/test/app-tap/tap.test.lua b/test/app-tap/tap.test.lua index 0e1de7f1c..a810be3f6 100755 --- a/test/app-tap/tap.test.lua +++ b/test/app-tap/tap.test.lua @@ -20,7 +20,7 @@ test.trace = false -- ok, fail and skip predicates -- -test:plan(32) -- plan to run 3 test +test:plan(33) -- plan to run 3 test test:ok(true, 'true') -- basic function local extra = { state = 'some userful information to debug on failure', details = 'a table argument formatted using yaml.encode()' } @@ -136,6 +136,20 @@ test:test('like', function(t) t:unlike('abcde', 'acd', 'unlike(abcde, acd)') end) +-- The test case implicitly checks that locals will not be printed while +-- checking the plan. +test:test('locals', function(t) + t.locals = true + t:plan(1) + t:test('locals nested', function(t) + local a = 42 + local tuple = box.tuple.new({}) + t:plan(2) + t:ok(true, 'locals are not printed in case of success') + t:fail('locals are printed in case of fail') + end) +end) + -- -- Finish root test. Since we used non-callback variant, we have to -- call check explicitly.