strange error in t/examples/pod.t

[mikehh]

t/examples/pod.t is failing with a weird error:

as of RELEASE_3_2_0-330-gae4f8e1 (after Merge branch 'whiteknight/imcc_compreg_pmc')

mhw@mhw-Desktop:~/parrot$ date
Fri Apr  8 18:26:45 BST 2011
mhw@mhw-Desktop:~/parrot$ prove t/examples/pod.t
t/examples/pod.t .. Failed 1/613 subtests

Test Summary Report
-------------------
t/examples/pod.t (Wstat: 0 Tests: 612 Failed: 0)
  Parse errors: Tests out of sequence.  Found (336) but expected (335)
                Tests out of sequence.  Found (337) but expected (336)
                Tests out of sequence.  Found (338) but expected (337)
                Tests out of sequence.  Found (339) but expected (338)
                Tests out of sequence.  Found (340) but expected (339)
Displayed the first 5 of 279 TAP syntax errors.
Re-run prove with the -p option to see them all.
Files=1, Tests=612, 42 wallclock secs ( 0.48 usr  0.02 sys +  9.28 cusr  5.77 csys = 15.55 CPU)
Result: FAIL

running prove -p t/examples/pod.t ->

mhw@mhw-Desktop:~/parrot$ prove -p t/examples/pod.t
t/examples/pod.t .. Failed 1/613 subtests

Test Summary Report
-------------------
t/examples/pod.t (Wstat: 0 Tests: 612 Failed: 0)
  Parse errors: Tests out of sequence.  Found (336) but expected (335)
                Tests out of sequence.  Found (337) but expected (336)
                Tests out of sequence.  Found (338) but expected (337)
...
...
                Tests out of sequence.  Found (612) but expected (611)
                Tests out of sequence.  Found (613) but expected (612)
                Bad plan.  You planned 613 tests but ran 612.
Files=1, Tests=612, 39 wallclock secs ( 0.49 usr  0.02 sys +  7.53 cusr  5.32 csys = 13.36 CPU)
Result: FAIL

extract from prove -v t/examples/pod.t ->

mhw@mhw-Desktop:~/parrot$ prove -v t/examples/pod.t
t/examples/pod.t ..
ok 1 - docs/dev/byteorder.pod:15:PIR:FRAGMENT
not ok 2 - docs/pdds/pdd23_exceptions.pod:372:PIR:FRAGMENT_TODO # TODO invalid code
#   Failed (TODO) test 'docs/pdds/pdd23_exceptions.pod:372:PIR:FRAGMENT_TODO'
#   at t/examples/pod.t line 79.
#          got: 'error:imcc:syntax error, unexpected DOT ('.')
#       in file '/tmp/82LPPD9Iwc.pir' line 4
# error:imcc:syntax error, unexpected DOT ('.')
#       in file '/tmp/82LPPD9Iwc.pir' line 6
# error:imcc:syntax error ... somewhere
#       in file '/tmp/82LPPD9Iwc.pir' line 8
# syntax error ... somewhere
# '
#     expected: ''
ok 3 - docs/pdds/pdd23_exceptions.pod:395:PIR:FRAGMENT
...
...
ok 333 - docs/pdds/pdd19_pir.pod:456:PIR:
ok 334 - docs/pdds/pdd19_pir.pod:481:PIR:
4243ok 335 - docs/pdds/pdd19_pir.pod:491:PIR:
ok 336 - docs/pdds/pdd19_pir.pod:510:PIR:
not ok 337 - docs/pdds/pdd19_pir.pod:531:PIR:INVALID # TODO invalid code
#   Failed (TODO) test 'docs/pdds/pdd19_pir.pod:531:PIR:INVALID'
#   at t/examples/pod.t line 79.
#          got: 'error:imcc:'bar' is not a vtable, but was used with :vtable.
#
#       in file '/tmp/VwQGZ9XhqZ.pir' line 4
# '
#     expected: ''
ok 338 - docs/pdds/pdd19_pir.pod:662:PIR:FRAGMENT
ok 339 - docs/pdds/pdd19_pir.pod:682:PIR:FRAGMENT
...
...
ok 612 - docs/user/pir/exceptions.pod:67:PIR:FRAGMENT
ok 613 - docs/user/pir/exceptions.pod:92:PIR:
1..613
Failed 1/613 subtests

Test Summary Report
-------------------
t/examples/pod.t (Wstat: 0 Tests: 612 Failed: 0)
  Parse errors: Tests out of sequence.  Found (336) but expected (335)
                Tests out of sequence.  Found (337) but expected (336)
                Tests out of sequence.  Found (338) but expected (337)
                Tests out of sequence.  Found (339) but expected (338)
                Tests out of sequence.  Found (340) but expected (339)
Displayed the first 5 of 279 TAP syntax errors.
Re-run prove with the -p option to see them all.
Files=1, Tests=612, 43 wallclock secs ( 0.67 usr  0.03 sys +  9.29 cusr  5.77 csys = 15.76 CPU)
Result: FAIL

notice the 4243ok 335.. this seems to me where things go wrong

mhw@mhw-Desktop:~/parrot$ ack 'Tests out of sequence.'
runtime/parrot/library/TAP/Parser.pir
1254:    self.'_add_error'("Tests out of sequence.  Found (", $S1, ") but expected (", $S2, ")")

looks like it fails somewhere in docs/pdds/pdd19_pir.pod

[jkeenan]

I am getting the same results on linux/i386, with no special configuration options.

kid51

[jkeenan]

t/examples/pod.t constructs a list of files with POD to be analyzed during this test. I bisected that list to try to determine at which point in the list the errors reported by mikehh first appeared.

The miscreant: docs/pdds/pdd19_pir.pod. Omitting this file from the list of files to be analyzed enables t/examples/pod.t to complete successfully.

Furthermore, when you limit the list of files to be analyzed to just this file, the error is reproduced:

prove -v t/examples/pod.t ... 1..45
Failed 1/45 subtests

Test Summary Report

t/examples/pod.t (Wstat: 0 Tests: 44 Failed: 0)

    Parse errors: Tests out of sequence. Found (16) but expected (15)
...
Displayed the first 5 of 31 TAP syntax errors.
Re-run prove with the -p option to see them all.
Files=1, Tests=44, 9 wallclock secs 
  ( 0.21 usr 0.05 sys + 1.94 cusr 2.14 csys = 4.34 CPU) Result: FAIL

I hypothesized that the parts of this file touched during the imcc_compreg branch work would be the points of failure. I tried removing each of two PIR blocks whiteknight touched recently, but this did not enable the test to pass.

More eyeballs needed.

kid51

[jkeenan]

Bisection of "docs/pdds/pdd19_pir.pod" itself shows that when this block beginning at line 491 is deleted, the test passes.

=begin PIR

    .sub foo :immediate
        print '42'
    .end

    .sub bar :postcomp
        print '43'
    .end

=end PIR

[mikehh]

I get the same.

If you look at my original report the line in prove -v

4243ok 335 - docs/pdds/pdd19_pir.pod:491:PIR:

so it looks as though the print statement is actually being executed by imcc

Cheers, Michael (mikehh)

[mikehh]

Looking at docs/ppds/pdd19.pit on github with blame, those lines have not been changed since 2008.

So I would suggest that the branch merge 'whiteknight/imcc_compreg_pmc' has changed the behavior of print. This needs to be investigated.

Cheers, Michael (mikehh)

[cotto]

This happens because the example code writes to stdout in an :immediate sub, messing up the TAP output. I changed the example code to not output anything in da70a78, which fixes the issue. plobsing++ for describing the cause of this.