[tarantool-patches] Re: [PATCH] lua: show locals when a tap test fails

[Alexander Turenko <alexander.turenko@tarantool.org>]

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.