Skip to content

some output of print() during tests is lost #4

@flrgh

Description

@flrgh

👋

On the success or pending case in handler.testEnd(), htest moves the cursor up by one line before printing a formatted string that contains the ESC[K sequence to clear the line. This works nicely to clear the prior ....... RUN [...] line in most cases. However, when something in a test attempts to write to stdout/stderr, this has the effect of lopping off the last line of that output rather than the intended line:

describe("output", function()
  it("nothing", function()
  end)

  it("io.write()", function()
    io.write("1\n")
    io.write("2\n")
    io.write("3\n") -- will not be visible
    io.flush()
  end)

  it("print()", function()
    print("1")
    print("2")
    print("3") -- will not be visible
    io.flush()
  end)

  it("io.stderr:write()", function()
    io.stderr:write("1\n")
    io.stderr:write("2\n")
    io.stderr:write("3\n") -- will not be visible
    io.stderr:flush()
  end)
end)
$ busted -o htest demo_spec.lua
======= Running tests from scanned files.
------- Global test environment setup.
------- Running tests from demo_spec.lua :
   0.02   OK 2: output nothing
.......  RUN 5: output io.write()
1
2
   0.04   OK 5: output io.write()
.......  RUN 12: output print()
1
2
   0.04   OK 12: output print()
.......  RUN 19: output io.stderr:write()
1
2
   0.09   OK 19: output io.stderr:write()
------- 4 tests from demo_spec.lua (0.67 ms total)

------- Global test environment teardown.
======= 4 tests from 1 test file ran. (0.82 ms total)
PASSED  4 tests.

It's pretty confusing in practice. This is the "best" case scenario where there is >1 lines of output produced during a test case. What's more common is for a test case to produce 1 line of output, which is wholly swallowed and leaves you wondering "did my code run?"

For comparison, TAP:

$ busted -o TAP demo_spec.lua
ok 1 - output nothing
1
2
3
ok 2 - output io.write()
1
2
3
ok 3 - output print()
1
2
3
ok 4 - output io.stderr:write()
1..4

I'm actually not sure what should be done about this. Each print() represents something that may or may not be called from a random place in the call stack, so it's not straightforward to simply emit an extra newline after the "last" print() in a test case (and emitting an extra newline on every print() will make the output ugly).

An engineer-y solution might be to add a logging API to busted which ultimately is passed through to the output handler so it can handle things appropriately and not stomp on test log output. Seems like a bunch of effort for such a small problem, and then busted needs to decide if it should monkey patch print()/io.* functions to use this API or just let old code remain broken.

Maybe there's a smarter escape code sequence that can be used instead? Check the cursor position to see if it's changed and don't clear the line in that case? Meticulously save the cursor position of $line_we_want_to_clear such that we can traverse back there and erase it specifically?

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions