Re^2: Test::Harness bug ? ... or author idiocy ?

If you can supply a reproducible test case then no doubt others could test and determine if it is indeed an MSWin32-only issue.

Actually I can (and just have) tested it out on Ubuntu, perl-5.34.0 and it's the same issue.

Here's an Inline::C demo of the problem:
Firstly, with the printf() statement commented out:

use strict;
use warnings;

use Inline C => <<'EOC';

SV * foo( SV * in ) {
   /*  printf("# %s\n", SvPV_nolen(in)); */
   return newSVpv(SvPV_nolen(in), 0);
}

EOC

my $ok = 1;

print "1..1\n";

for(1 .. 1000) {
  my $n = int(rand(10000000));
  $ok = 0 if foo("$n") ne "$n";
}

if($ok) { print "ok 1\n" }
else {
  print "not ok 1\n";
}

__END__
[download]

I first run perl try.pl to compile the script, and then I run:

$ perl -MTAP::Harness -e '$h = TAP::Harness->new(); $h->runtests("./tr
+y.pl");'
./try.pl .. ok
All tests successful.
Files=1, Tests=1,  0 wallclock secs ( 0.04 usr  0.01 sys +  0.06 cusr 
+ 0.01 csys =  0.12 CPU)
Result: PASS
[download]

As you can see, everything is fine. But if I then include the printf() statement and run perl try.pl (to recompile the script), upon re-testing I get:

 $ perl -MTAP::Harness -e '$h = TAP::Harness->new(); $h->runtests("./t
+ry.pl");'
./try.pl .. All 1 subtests passed

Test Summary Report
-------------------
./try.pl (Wstat: 0 Tests: 1 Failed: 0)
  Parse errors: No plan found in TAP output
Files=1, Tests=1,  1 wallclock secs ( 0.11 usr  0.01 sys +  0.05 cusr 
+ 0.02 csys =  0.19 CPU)
Result: FAIL
[download]

Cheers,
Rob

Comment on Re^2: Test::Harness bug ? ... or author idiocy ? Select or Download Code

Replies are listed 'Best First'.
Re^3: Test::Harness bug ? ... or author idiocy ? by hippo (Bishop) on Nov 06, 2021 at 12:04 UTC
Thanks for this example. I have run your code with the printf uncommented and reproduced your findings (on Linux) but only on some runs. The result is inconsistent. Here is the output from 2 runs within a few seconds of each other: 10045 $ perl -MTAP::Harness -e '$h = TAP::Harness->new(); $h->runtests +("./11138492.pl");' ./11138492.pl .. ok All tests successful. Files=1, Tests=1, 0 wallclock secs ( 0.06 usr 0.00 sys + 0.04 cusr + 0.00 csys = 0.10 CPU) Result: PASS 10046 $ perl -MTAP::Harness -e '$h = TAP::Harness->new(); $h->runtests +("./11138492.pl");' ./11138492.pl .. All 1 subtests passed Test Summary Report ------------------- ./11138492.pl (Wstat: 0 Tests: 1 Failed: 0) Parse errors: No plan found in TAP output Files=1, Tests=1, 0 wallclock secs ( 0.06 usr 0.01 sys + 0.04 cusr + 0.00 csys = 0.11 CPU) Result: FAIL [download] However, upon inspection the problem is not with TAP::Harness. The output of just running the script shows that the plan can appear in the middle of your data. Again, running a few times gives: `10046 $ perl 11138492.pl \| grep -Fn 1..1 830:# 79678951..1 10047 $ perl 11138492.pl \| grep -Fn 1..1 830:# 691..1 10047 $ perl 11138492.pl \| grep -Fn 1..1 829:# 5056771..1` [download] So this looks to be a buffering issue. If I simply modify your code to include `$\|++;` before the plan is printed then the script runs fine, the plan is printed at the top and the test harness has no complaints. Not a bug in Test::Harness after all. 🦛	[reply] [d/l] [select]
Re^4: Test::Harness bug ? ... or author idiocy ? by syphilis (Archbishop) on Nov 06, 2021 at 12:57 UTC
Not a bug in Test::Harness after all. Cool ... creating bug reports always ends up in being more work than one anticipates. Thank you !! If I simply modify your code to include $\|++; before the plan is printed then the script runs fine I thought that `print "1..1\n"` should flush the buffer immediately (because of the "\n") without any need to increment `$\|`. And this notion is supported by the following one-liner that prints out a "." followed by a newline every second for 10 seconds: `$ perl -e 'for(1..10) {print ".\n"; sleep 1}'` [download] whereas this next one-liner (as expected) prints nothing for 10 seconds, and then immediately prints out all 10 dots: `$ perl -e 'for(1..10) {print "."; sleep 1}'` [download] I don't doubt that I'm missing something pretty basic ... and I shudder to think what the answer might be .... but I'll ask the question "what is it that I'm missing ?", anyway ;-) Cheers, Rob	[reply] [d/l] [select]
Re^5: Test::Harness bug ? ... or author idiocy ? by hippo (Bishop) on Nov 06, 2021 at 13:53 UTC
Your trivial examples are printing to the shell, presumably in a terminal. That is what makes it default to autoflush. Redirect that output and it's a different story. Compare: `$ perl -e 'for(1..10) {print ".\n"; sleep 1}' \| sed -e 's/\./#/g'` [download] with `$ perl -e '$\|++; for(1..10) {print ".\n"; sleep 1}' \| sed -e 's/\./#/g +'` [download] See the excellent Suffering from Buffering (particularly the section Hot and Not Hot) for more on this. When something else is wrapping the STDOUT, like your test harness for example, then the autoflushing is no longer applied by default. Everything in Perl should still be printed in the right order but I expect that the `printf` output in the C part is bypassing the higher-level buffer (just a guess - I don't know enough about how Inline::C works to say for sure). 🦛	[reply] [d/l] [select]
Re^6: Test::Harness bug ? ... or author idiocy ? by syphilis (Archbishop) on Nov 06, 2021 at 23:25 UTC
Re^3: Test::Harness bug ? ... or author idiocy ? by Anonymous Monk on Nov 06, 2021 at 07:19 UTC
Plan has to go first. This is TAP. http://testanything.org/tap-specification.html	[reply]
Re^4: Test::Harness bug ? ... or author idiocy ? by syphilis (Archbishop) on Nov 06, 2021 at 10:20 UTC
Plan has to go first Sorry - I'm not clever enough to grasp your point. AFAICS, the "Plan" is in exactly the same location, irrespective of whether the printf() statement is included or not. Cheers, Rob	[reply]


No such thing as a small change
	PerlMonks