Test output gets swallowed when --jobs > 1

[oalders]

I had opened houseabsolute/test-class-moose#108 on Test::Class::Moose, but @exodist suggested that I also open a ticket here, since the problem described above may actually be an issue with prove.

The original tickets demonstrates this issue and also contains a repository which can be used to replicate it.

[oalders]

Hello Gang!

Is there anything I can do here to help get this sorted?

[Leont]

Does this problem only occur on the console, or also when it's redirected to a file? And does it also happen when it's teeed to a file?

[oalders]

Good question. The problem does not occur when I redirect to a file.

$ prove -v --jobs 2 t/runner.t &> foo.txt
$ cat foo.txt
        #   Failed test at t/lib/TestFor/DateTime.pm line 10.
    # Failed test 'test_constructor'
    # at /Users/olafalders/.plenv/versions/5.30.3/lib/perl5/site_perl/5.30.3/Test2/Tools/AsyncSubtest.pm line 23.

# Failed test 'TestsFor::DateTime'
# at /Users/olafalders/.plenv/versions/5.30.3/lib/perl5/site_perl/5.30.3/Test2/Tools/AsyncSubtest.pm line 23.
# Looks like you failed 1 test of 1.
t/runner.t ..
1..1
not ok 1 - TestsFor::DateTime {
    1..1
    not ok 1 - test_constructor {
        not ok 1
        ok 2 - DateTime->can('new')
        ok 3 - An object of class 'DateTime' isa 'DateTime'
        ok 4 - ... and the year should be correct
        1..4
    }
}
# IPC is waiting for children to finish...
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/1 subtests

Test Summary Report
-------------------
t/runner.t (Wstat: 256 Tests: 1 Failed: 1)
  Failed test:  1
  Non-zero exit status: 1
Files=1, Tests=1,  1 wallclock secs ( 0.02 usr  0.00 sys +  0.54 cusr  0.05 csys =  0.61 CPU)
Result: FAIL

It looks to work correctly via tee as well:

0$ prove -v --jobs 2 t/runner.t |& tee
        #   Failed test at t/lib/TestFor/DateTime.pm line 10.
    # Failed test 'test_constructor'
    # at /Users/olafalders/.plenv/versions/5.30.3/lib/perl5/site_perl/5.30.3/Test2/Tools/AsyncSubtest.pm line 23.

# Failed test 'TestsFor::DateTime'
# at /Users/olafalders/.plenv/versions/5.30.3/lib/perl5/site_perl/5.30.3/Test2/Tools/AsyncSubtest.pm line 23.
# Looks like you failed 1 test of 1.
t/runner.t ..
1..1
not ok 1 - TestsFor::DateTime {
    1..1
    not ok 1 - test_constructor {
        not ok 1
        ok 2 - DateTime->can('new')
        ok 3 - An object of class 'DateTime' isa 'DateTime'
        ok 4 - ... and the year should be correct
        1..4
    }
}
# IPC is waiting for children to finish...
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/1 subtests

Test Summary Report
-------------------
t/runner.t (Wstat: 256 Tests: 1 Failed: 1)
  Failed test:  1
  Non-zero exit status: 1
Files=1, Tests=1,  1 wallclock secs ( 0.02 usr  0.00 sys +  0.52 cusr  0.05 csys =  0.59 CPU)
Result: FAIL

For the record, the incorrect output was:

$ prove -v --jobs 2 t/runner.t

not ok 1 - TestsFor::DateTime {
        #   Failed test at t/lib/TestFor/DateTime.pm line 10.
    # Failed test 'test_constructor'
    # at /Users/olafalders/.plenv/versions/5.30.3/lib/perl5/site_perl/5.30.3/Test2/Tools/AsyncSubtest.pm line 23.

# Failed test 'TestsFor::DateTime'
# at /Users/olafalders/.plenv/versions/5.30.3/lib/perl5/site_perl/5.30.3/Test2/Tools/AsyncSubtest.pm line 23.
# Looks like you failed 1 test of 1.
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/1 subtests

Test Summary Report
-------------------
t/runner.t (Wstat: 256 Tests: 1 Failed: 1)
  Failed test:  1
  Non-zero exit status: 1
Files=1, Tests=1,  0 wallclock secs ( 0.02 usr  0.00 sys +  0.51 cusr  0.06 csys =  0.59 CPU)
Result: FAIL

[Leont]

Good question. The problem does not occur when I redirect to a file.

That means it's an issue in TAP::Formatter::Console::ParallelSession. Apparently it doesn't implement the concept of verbose mode (but for some things falls back to the non-parallel, so that's why you're seeing some output iff there is only one running test).