Test output blocks until test class is finished

[Ovid]

Consider the following code:

#!/usr/bin/env perl

package TestExample {
    use Test::Class::Moose;

    sub test_method {
        ok 'first';
        ok 'second';
        sleep 10;
        ok 'third';
    }
}
use Test::Class::Moose::Runner;
Test::Class::Moose::Runner->new->runtests;

That prints out:

1..1
ok 1 - TestExample {
    1..1
    ok 1 - test_method {
        ok 1
        ok 2
        ok 3
        1..3
    }
}
ok
All tests successful.
Files=1, Tests=1, 11 wallclock secs ( 0.02 usr  0.00 sys +  0.33 cusr  0.03 csys =  0.38 CPU)
Result: PASS

But I see none of that output until after the test class is completed (note the sleep 10). We have some extremely long running tests and sometimes it's nice to run them in verbose mode, but this means our tests hang and then we get a huge dump of output instead of seeing things as they go along.

Compare to this Test::More code:

#!/usr/bin/env perl

use strict;
use warnings;
use Test::More;

subtest 'TestExample' => sub {
    subtest "test_method" => sub {
        ok 'first';
        ok 'second';
        sleep 10;
        ok 'third';
    };
};
done_testing;

That prints out:

# Subtest: TestExample
    # Subtest: test_method
        ok 1
        ok 2
        ok 3
        1..3
    ok 1 - test_method
    1..1
ok 1 - TestExample
1..1
ok
All tests successful.
Files=1, Tests=1, 10 wallclock secs ( 0.02 usr  0.00 sys +  0.07 cusr  0.01 csys =  0.10 CPU)
Result: PASS

But the first output shows up before the sleep. Why is Test::Class::Moose output blocking until the end of the test class?

[exodist]

let me give you some background info to help you out:

Test2 provides 2 types of subtest, "streamed" and "buffered".

Streamed is the type you are used to that outputs a comment indicating the subtest is starting, outputs results in realtime (indented) and then outputs a final OK summarizing the subtest.

Buffered is a new style where the output is buffered until the subtest is complete, then it outputs an ok that ends with a '{' then the subtest events are rendered indented followed by an unindented '}'.

The buffered style was introduced to solve issues with subtests + concurrency within a test file. If you have a test file that forks, and both processes run subtests, the subtest events would be mixed together. This is not a problem for vanilla prove as it takes the approach of completely ignoring indented output, so it only cares about the final subtest OK's. That said it is not a pleasant experience for humans, or for harnesses that do actually parse subtests (like yath, and I believe some other tools that parse TAP output).

Test2 provides both types, and you are free to use either. See https://metacpan.org/pod/Test2::Tools::Subtest which provides both. They are also both compatible in that you can nest either under either, though nesting a streaming subtest under a buffered one is sill as the "streamed" output will still be buffered by its parent.

There is no global switch, or anything that forces you to use only one at a time. There are no strong opinions forcing you one way or the other either. The only catch is that if you want to use concurrency within a single test, and want to use subtests, and use a harness or parser that does parse subtests, it will likely barf on the streamed style.

I believe that Test::Class::Moose simply chose the buffered style (it should be easy enough to switch it, I believe it is a single option to a subtest subroutine). However if Test::Class::Moose does provide in-test concurrency switching may be a bad idea. I know many people and companies (myself and my employer included) use TCM + concurrency + yath which makes buffered the only viable option. That said I doubt it would be hard to add an option to Test::Class::Moose that lets you control it.

That said I know very little of the internals of Test::Class::Moose and personally avoid the framework when I can, so I cannot point you to the right code or anything. For Test2's part it is super simple, see the code for the subtest module I linked above: https://metacpan.org/release/Test2-Suite/source/lib/Test2/Tools/Subtest.pm It is a single option 'buffered => BOOL'

Hope that explanation helps!

[exodist]

Ah, actually, it looks like it would NOT be easy.

TCM uses AsyncSubtest (which is necessary fro some of its concurrency) and by its very nature that subtest library demands buffered.

[exodist]

https://github.com/houseabsolute/test-class-moose/blob/master/lib/Test/Class/Moose/Executor/Parallel.pm

[autarch]

Aha, this is all coming back to me. I remember digging into this quite a bit when I moved TCM to Test2. Yes, we have to use the buffered output for TCM because we might be doing parallel execution. And since TCM executes each class a giant subtest, you end up buffering the entire class's execution.

In theory we could use streaming in the sequential executor but I wanted to keep things simple so I just used buffered everywhere.

I don't know that there are any good fixes here given how TAP works.

[exodist]

I will point out that if you use yath instead of prove it does show you the buffered events as they happen, but it does so in a way that doesn't hurt anyone. Specifically as long as STDOUT is a real terminal it will output each event it sees, then erase it to show the next one, then write a line permanently when it is no longer just a buffered event. Which is kind of the best of both worlds. There is no way I know of to get similar behavior with TAP+Prove.

[exodist]

@Ovid sounds like to get what you want you need to submit a patch that makes the sequential executor use unbuffered subtests (not asynsubtests), but leave the parallel one using async-subtests.

[autarch]

@Ovid sounds like to get what you want you need to submit a patch that makes the sequential executor use unbuffered subtests (not asynsubtests), but leave the parallel one using async-subtests.

That would sort of fix it, but I would guess @Ovid is using parallel tests. If you have a large test suite using TCM it's pretty much required for performance.

[exodist]

Another option would be to add an inheritable listener onthe root hub that outputs something for any/all events, but something that does not get picked up by TAP or any other parsers, like printing a comment that is a status of what passed or something. That will give him ongoing feedback without interfering with anything

[exodist]

https://metacpan.org/pod/Test2::Hub#LISTENING-FOR-EVENTS

https://metacpan.org/pod/release/EXODIST/Test-Simple-1.302168/lib/Test2/API.pm#$stack-=-test2_stack()

https://metacpan.org/pod/Test2::Manual::Anatomy::Hubs

use Test2::API qw/test2_stack/;
my $hub = test2_stack->top;
$hub->listen(sub { ... }, inherit => 1}

[exodist]

He could also write his own formatter:

https://metacpan.org/pod/Test2::Formatter
Note the hide_buffered() sub, it returns true for TAP. In his own formatter he could have that method return false, then he will see buffered events as they happen as well as at the end, he would just need to be sure to have his formatter render them in a non-tap way to avoid harness issues. He can subclass the TAP formatter and intercept+render buffered events.

[exodist]

@Ovid:

#!/usr/bin/env perl

package TestExample {
    use Test::Class::Moose;
    {   
        no warnings 'redefine';
        *Test2::Formatter::TAP::hide_buffered = sub { 0 };
    }

    sub test_method {
        ok 'first';
        ok 'second';
        sleep 10;
        ok 'third';
    }
}

use Test::Class::Moose::Runner;
Test::Class::Moose::Runner->new->runtests;

This simple change makes it so you see the events as they happen as well as the final one, all you need to do is subclass with this change, and modify your subclass to also make the buffered events pretty and non-tap

Current output of just this:

1..1
    1..1
        ok 1
        ok 2
        ok 3
        1..3
    ok 1 - test_method {
        ok 1
        ok 2
        ok 3
        1..3
    }
ok 1 - TestExample {
    1..1
    ok 1 - test_method {
        ok 1
        ok 2
        ok 3
        1..3
    }
}