capturing debug output

[Niko Matsakis]

Hello,

I am wondering: is there an elegant way to emit debug messages that
are only printed when a test fails? Right now I just print out with
println(), but this doesn't really let you keep the debug messages in
place even once the tests start passing. I'd love something like
py.test's feature [1], which captures stdout and replays it only in
error-- although it'd be even better to just have a debug stream that
goes to /dev/null except during active testing.

Anyway, just curious if a feature like this already existed.

Thanks!

Niko

[1] http://codespeak.net/py/dist/test/features.html#extensive-debugging-support

[Bill Venners]

Hi Niko,

On Fri, Jun 19, 2009 at 6:19 AM, Niko Matsakis <nikoma...@gmail.com> wrote:
>
> Hello,
>
> I am wondering: is there an elegant way to emit debug messages that
> are only printed when a test fails?  Right now I just print out with
> println(), but this doesn't really let you keep the debug messages in
> place even once the tests start passing.  I'd love something like
> py.test's feature [1], which captures stdout and replays it only in
> error-- although it'd be even better to just have a debug stream that
> goes to /dev/null except during active testing.
>
> Anyway, just curious if a feature like this already existed.

Not exactly. There is a way you can send debug messages to the report.
They go via infoProvided method invocations on the reporter. However
they will always be printed out, not just when there's a test failure.
It isn't a bad idea, so let me think about how to do that. I'll also
check out what the python tool does.

Which trait are you using? In Suite, you can say:

def testSomething(info: Informer) {

// ...
info("send debug message like this")
// ...
}

In FunSuite, you can say:

test("something") {

// ...
info("send debug message like this")
// ...
}

Unfortunately in Spec I didn't yet put the info in there in time for
0.9.5. So that's a bit trickier, but can be done. If you are using
Spec let me know and I'll post how to do it in 0.9.5.

Now that I think about it, it could look something like:

debug("bla bla bla")

which would only go out the door when a test fails. I wonder how many
people use this style and would want such a feature.

Thanks.

Bill

>
> Thanks!
>
> Niko
>
> [1] http://codespeak.net/py/dist/test/features.html#extensive-debugging-support
> >

--
Bill Venners
Artima, Inc.
http://www.artima.com

[Erick Fleming]

+1 for debug("...")

[Joakim Ohlrogge]

I have been toying with that idea for tests and production systems. Basically, in a prodsystem, log to a rotating memory buffer and upon an exception, dump the log-buffer all the way down to the debug-level.

That would be nice for tests too. In general I don't want to add printlns/debug-statements in my tests/specs but I would like to run my code /under test/ with full logging enabled sometimes and it would be nice to have stdout "swallowed" until a test fails and see only the relevant output generated under that particular test. It would be simple enough to replace System.out with your own printstream in order to capture and/or hide the output.

An additional benefit of having ScalaTest intercept System.out and System.err is that it would be possible to present the relevant ouput with the test that emitted it.

+1 for intercepting System.out + System.err

--
-----------------------------------------------------
Joakim Ohlrogge
Agical AB
Västerlånggatan 79, 2 tr
111 29 Stockholm, SWEDEN

Mobile: +46-708-754004
Blog: johlrogge.wordpress.com
E-mail: joakim....@agical.se

[Bill Venners]

Hi All,

I may be hearing two different needs here. One is debug messages
written directly with println, the other is log messages through a
logger. There's also the question of debug/log messages printed out in
the tests themselves versus by the code under test. If the logger
could be configured to write to standard output or error during the
tests, then it collapses into one problem of capturing standard output
and error streams, which is easy enough in a sequential scenario on
the JVM, more tricky in a multi-threaded one.

Is the desire to capture and only show output for failed tests that is
produced by the test code versus the production code under test, or
both? Which is more important?

Thanks.

Bill

[Niko Matsakis]

I do indeed think there are two slightly different features being
discussed, but probably either would be sufficient for me. I tend to
debug by logging all relevant information into a file and then sifting
through it later -- debuggers have the unfortunate tendency to stop
right AFTER they've taken a wrong step, whereas what I generally need
is to be able to stop right BEFORE.

For this purpose, it's very important to be able to insert printouts
into the code under test, and not only the test code. That's usually
where the juicy internal state can be found. It seems like info()
only permits inserting printouts into the test code itself.

What py.test does is essentially to redirect the Python equivalent of
System.out and System.err. This is very handy, and I would be happy
with it in scalatest as well, though as you point out it may have
strange ramifications if you are trying to run scalatest in a multi-
threaded VM simultaneously with other code. Perhaps just providing an
option to disable/enable this behavior would solve that dilemma,
however.

In any case, if you do see fit to implement such a feature, whether by
redirecting System.out/System.err or by some scalatest-specific way, I
would be very grateful.


Niko

[Joakim Ohlrogge]

To direct ones preferred logging framework to std out is what I had in mind. My personal preference would be to be able to not see any output at all unless a test fails where you would se only the output produced during the failed test. I don't use multithreaded tests so that functionality is not important for me. I guess what I'm saying is that any reasonable way around the MT-issue is fine with me :)

Perhaps this feature could be implemented with something similar to JUnit interceptors? Then a scalatest user could do whatever he/she wants around each test, including intercepting stdout/stderr. But it would require being able to intercept on a "global" level and not just for one class at the time (as I understand is how it works in JUnit)

/J

[Bill Venners]

Hi Niko,

It would be easy to provide a trait, but it would only work in a single-threaded context. I think that is still useful. Even if you like to run tests concurrently usually, if you have a problem you can run them sequentially just long enough to debug the problem with this trait. The solution would be to provide a trait in ScalaTest that overrides runTest, and before calling super.runTest it would swap out System.out and System.err. After runTest returns, it would put the old System.out and System.err back. You can see why this wouldn't work in a multi-threaded context, because multiple instances of this thing would be trying to swap out System.out and System.err at the same time. It just wouldn't work. It is about a side-effecty approach as I can imagine, swapping out the standard out and err streams.

Anyway, I'll need to change runTest to return true if the test succeeded and false if not, so that this trait would know whether to report the captured standard out and error info. I think that's generally useful, so I'll make that change for 0.9.6. And what I think the trait should do is report it to the reporter via infoProvided messages, so that the capture output shows up in the test run report, right after the test failure is reported. That way you wouldn't have to go searching for the information and trying to match up standard out and error output with test run output. Plus this way it would show up in whatever form of output you like to get your reports in.

The usage of it would be kind of a pain I think, because most of the time I figure people will want to run tests concurrently. In 0.9.6, the reports generated will be in the same order when run concurrently as sequentially, so the only difference given multiple cores, which most people have, is that running concurrently will make your tests run faster. So if you do that, but then want to capture the standard error, you'd have to mix in this trait, then run them sequentially, then probably you'd want to unmix in (mix out?) the trait. That's a pain. Frankly I think it is too painful. Although if you always run sequentially it is easy as pie. Let me think if there's some way to allow you to leave the trait in all the time, but just disable its behavior or better yet do the right thing, if run in a multi-threaded context.

Bill

[Niko Matsakis]

Hmm, it occurs to me that I could perhaps write some code like:

def withDebug(testFunction: StringBuffer => Unit) {

val buffer = new StringBuffer()

try {

testFunction(buffer)

} catch {

case t: Throwable => 

info(buffer.toString)

throw t

}

}

Now, assuming I managed to arrange for my debug output to be channeled into the buffer, I would only get printouts if the test failed.  This is acting on the assumption that scala test verification methods throw exceptions on failure, which I believe is true, no?

Kind of similar to what you suggested as an alternate to tearDown here: http://www.artima.com/weblogs/viewpost.jsp?thread=232028

Niko

[Bill Venners]

Hi Joakim,

On Fri, Jun 19, 2009 at 12:13 PM, Joakim Ohlrogge <joakim....@gmail.com> wrote:

To direct ones preferred logging framework to std out is what I had in mind. My personal preference would be to be able to not see any output at all unless a test fails where you would se only the output produced during the failed test. I don't use multithreaded tests so that functionality is not important for me. I guess what I'm saying is that any reasonable way around the MT-issue is fine with me :)

OK. It sounds useful to people even with the caveat that it only works single-threaded. 

Perhaps this feature could be implemented with something similar to JUnit interceptors? Then a scalatest user could do whatever he/she wants around each test, including intercepting stdout/stderr. But it would require being able to intercept on a "global" level and not just for one class at the time (as I understand is how it works in JUnit)

ScalaTest doesn't need JUnit-like interceptors, if I understand them correctly, because ScalaTest has all those execute and run methods that can be overridden. That's I think the main difference between ScalaTest and xUnit. In xUnit, the framework runs the tests from the outside. In ScalaTest, you ask a suite of tests to run itself. So for example, if you want to intercept control every time a ScalaTest suite runs a test, you override runTest, as I described in my previous email to Niko. If you want to replace the standard output globally, before everything is run, you could either override execute in a outermost Suite (or mix in BeforeAndAfter and use beforeAll() and afterAll()). However, this wouldn't work if you're using suite discovery to run tests. That's what I use all the time, so I don't have an outermost suite that I could change like this. (The outermost suite in that case is DiscoverySuite, which is internal to ScalaTest.) It makes me wonder if there's a need for some way to specify stuff that runs before and after a run. I'd rather not do that, since there's already a good way to do that with suites. But that approach doesn't work with suite discovery. The alternative would be to have a command line option in Runner that will replace System.out and System.err with /dev/null like things that just eat all output. Sounds like a good recipe for people being completely baffled as to why there's no output when ...

Oh darn, I just thought of a problem. People probably often print test results to the standard output. That's going out via a different thread, which is running in an actor. Basically it seems like people would want that output still, right? I'll think about this during lunch and see if there's some way that the replacement streams can figure out where something is coming from. Actually I can already see how it would let test reports out. That would be pretty easy.

So let me ask, would you not want to see test reports sent to the standard output stream, say, if you picked that. For example, output like this:

[scalatest] Suite Starting - DiscoverySuite

[scalatest] The run method of a nested suite is about to be invoked.

[scalatest] An Ordinal 

[scalatest] - should produce a runStamp :: N on nth next

[scalatest] - should produce a runStamp :: 0 ... n times on nth nextNewOldPair

[scalatest] - should produce a runStamp :: 0 :: 1 :: 2 :: ... :: n on nth next ad nextNewOldPair

[scalatest] - should produce a pair of Ordinals with _1.toList.length one less than _2.toList.length after nextNewOldPair is invoked

[scalatest] - should produce a pair of Ordinals whose n - 1 and n elements are less than by 1 when nextNewOldPair is invoked

[scalatest] - should produce an Ordinal that is greater than this when either next or nextNewOldPair is invoked

[scalatest] - should produce equal Ordinals given the same series of next and nextNewOldPair calls, unequal otherwise

[scalatest] - should produce Ordinals that have equals hashCodes given the same series of next and nextNewOldPair calls

[scalatest] The run method of a nested suite is about to be invoked.

[scalatest] Suite Completed - DiscoverySuite

And what you'd want suppressed would be anything sent out from println's you wrote in tests, or production code, or through loggers configured to print to the standard output, etc? (Suppressed unless a test fails, in which case you'd want to see what got printed out during that test.)

Bill

[Bill Venners]

Hi Niko, Joakim,

Actually I think the way to make this simple to use is to have a trait such as OutAndErrWitholding, which you mix into the top level suite. Or use a command line param to Runner so it will mix it into the top level suite when performing discovery. This guy would replace System.out and err before doing anything else, and replace back the old ones in a finally block. During the run, ScalaTest's normal procedure would be to look for the special System.out and err after a failed test, and if it is there, go ahead and send the extra info via infoProvided reports. The best I think I can do is send an initial infoProvide giving the thread name for the thread that ran the failed test, then print all output printed by any thread during the time the failed test was running, but prepend each bit of output with a thread name. That way you could in a multi-threaded context at least sort through and find the right ones that match your the thread name running the failed test. In a sequential run you would not need to do any sorting, but in a multi-threaded run you could still get at the info. The trouble with just pruning only messages by the thread that runs the test that failed is that your app might have other threads running during this time that have useful information, and the test could start more threads too.

Does that approach sound like it would grant your wish?

Thanks.

Bill

On Fri, Jun 19, 2009 at 12:02 PM, Niko Matsakis <nikoma...@gmail.com> wrote:

[Niko Matsakis]

Sounds like it would work, yes.

Niko

[Bill Venners]

Hi Niko,

On Fri, Jun 19, 2009 at 12:37 PM, Niko Matsakis <nikoma...@gmail.com> wrote:
>
> Hmm, it occurs to me that I could perhaps write some code like:
> def withDebug(testFunction: StringBuffer => Unit) {
> val buffer = new StringBuffer()
> try {
> testFunction(buffer)
> } catch {
> case t: Throwable =>
> info(buffer.toString)
> throw t
> }
> }
>
> Now, assuming I managed to arrange for my debug output to be channeled into the buffer, I would only get printouts if the test failed.  This is acting on the assumption that scala test verification methods throw exceptions on failure, which I believe is true, no?
> Kind of similar to what you suggested as an alternate to tearDown here: http://www.artima.com/weblogs/viewpost.jsp?thread=232028
>

Yes, that would work, so long as you're using FunSuite (Spec doesn't
have info() in 0.9.5. If you're using Spec, though, you can do info
yourself. Let me know if that's what you're doing and I'll show how
you can do it in 0.9.5 with Spec. Spec will have info in 0.9.6.). Your
captured debug info would show up just above the info for the failed
test in the report.

ScalaTest does use the same, traditional
throw-an-exception-to-indicate-test-failure in Suite, FunSuite, Spec,
etc. This allows people to use JUnit or TestNG assertions if they
prefer, or ScalaTest Assertions, MustMatchers, or ShouldMatchers, or
Specs Matchers. Also any kind of unexpected exception will cause a
test failure. When you use one of the ScalaTest options for assertions
or matchers, the exception that is thrown in called
TestFailedException, and it includes a nice bit of information
pointing to exactly the line of code test that caused the failure,
which saves you from scanning through the stack trace for it.

Thanks.

Bill