search

Test-More / Test2-Harness

Alternative to Test::Harness
Other
23 stars 26 forks source link

Top-level subtests with timeout failures hide all output from yath test -v and yath replay -v #230

Open wolfsage opened 3 years ago

wolfsage commented 3 years ago

If you have a test with a top-level subtest, and lots of tests fire in it and then eventually it hangs for --event-timeout seconds, the test is killed, and all of the output is ... hidden.

Consider: repro.t:

use Test::More;

subtest "all" => sub {
  subtest 'a' => sub {
    ok($_, "my test $_") for 1..10;
  };

  subtest 'b' => sub {
    ok($_, "my other test $_") for 1..10;

    sleep 10;
  };
};

done_testing;

$ yath test -v repro.t --event-timeout 3 --log-file foo
( LAUNCH )  job  1    repro.t
(  NOTE  )  job  1    Subtest: all
( TIMEOUT)  job  1    Test2::Harness checks for timeouts at a configurable interval, if a test does
( TIMEOUT)  job  1    not produce any output to stdout or stderr between intervals it will be
( TIMEOUT)  job  1    forcefully killed under the assumption it has hung. See the '--event-timeout'
( TIMEOUT)  job  1    option to configure the interval.
< TIMEOUT>  job  1    A timeout (event) has occured (after 3.0259 seconds), job was forcefully killed
( FAILED )  job  1    repro.t
(  TIME  )  job  1    Startup: 0.03077s | Events: 0.00000s | Cleanup: 2.99831s | Total: 3.02908s
< REASON >  job  1    Test script returned error (Signal: 15)
< REASON >  job  1    Errors were encountered (Count: 1)
< REASON >  job  1    No plan was declared, and no assertions were made.

The following jobs failed:
+--------------------------------------+-----------+
| Job ID                               | Test File |
+--------------------------------------+-----------+
| 7E802E3E-FAB6-11EB-A8A3-05960FBB74F1 | repro.t   |
+--------------------------------------+-----------+

                                Yath Result Summary
-----------------------------------------------------------------------------------
     Fail Count: 1
     File Count: 1
Assertion Count: 21
      Wall Time: 3.25 seconds
       CPU Time: 0.46 seconds (usr: 0.14s | sys: 0.01s | cusr: 0.26s | csys: 0.05s)
      CPU Usage: 14%
    -->  Result: FAILED  <--

And 

alh@emondsfield:~/pobox/git/fm/hm$ yath replay foo.jsonl -v
( LAUNCH )  job  1    repro.t
(  NOTE  )  job  1    Subtest: all
( TIMEOUT)  job  1    Test2::Harness checks for timeouts at a configurable interval, if a test does
( TIMEOUT)  job  1    not produce any output to stdout or stderr between intervals it will be
( TIMEOUT)  job  1    forcefully killed under the assumption it has hung. See the '--event-timeout'
( TIMEOUT)  job  1    option to configure the interval.
< TIMEOUT>  job  1    A timeout (event) has occured (after 3.0328 seconds), job was forcefully killed
( FAILED )  job  1    repro.t
(  TIME  )  job  1    Startup: 0.03052s | Events: 0.00000s | Cleanup: 3.00533s | Total: 3.03585s
< REASON >  job  1    Test script returned error (Signal: 15)
< REASON >  job  1    Errors were encountered (Count: 1)
< REASON >  job  1    No plan was declared, and no assertions were made.

The following jobs failed:
+--------------------------------------+-----------+
| Job ID                               | Test File |
+--------------------------------------+-----------+
| 903DE1CA-FAB6-11EB-8007-5D960FBB74F1 | repro.t   |
+--------------------------------------+-----------+

          Yath Result Summary
---------------------------------------
     Fail Count: 1
     File Count: 1
Assertion Count: 21
    -->  Result: FAILED  <--

But the events are there:

alh@emondsfield:~/pobox/git/fm/hm$ jq < foo.jsonl  | grep -i 'my.*test'
      "details": "my test 1",
        "name": "my test 1",
      "details": "my test 2"
        "name": "my test 2",
      "details": "my test 3",
        "name": "my test 3",
        "name": "my test 4",
      "details": "my test 4",
      "details": "my test 5",
        "name": "my test 5"
      "details": "my test 6",
        "name": "my test 6",
      "details": "my test 7"
        "name": "my test 7",
        "name": "my test 8",
      "details": "my test 8"
      "details": "my test 9"
        "name": "my test 9",
        "name": "my test 10",
      "details": "my test 10"
              "name": "my test 1"
            "details": "my test 1"
              "name": "my test 2",
            "details": "my test 2"
            "details": "my test 3"
              "name": "my test 3",
              "name": "my test 4",
            "details": "my test 4",
              "name": "my test 5",
            "details": "my test 5",
              "name": "my test 6",
            "details": "my test 6"
              "name": "my test 7",
            "details": "my test 7"
            "details": "my test 8"
              "name": "my test 8",
            "details": "my test 9",
              "name": "my test 9",
            "details": "my test 10",
              "name": "my test 10",
        "name": "my other test 1",
      "details": "my other test 1",
      "details": "my other test 2"
        "name": "my other test 2",
        "name": "my other test 3",
      "details": "my other test 3"
      "details": "my other test 4"
        "name": "my other test 4",
      "details": "my other test 5",
        "name": "my other test 5",
      "details": "my other test 6"
        "name": "my other test 6",
      "details": "my other test 7"
        "name": "my other test 7",
      "details": "my other test 8",
        "name": "my other test 8"
        "name": "my other test 9",
      "details": "my other test 9"
        "name": "my other test 10"
      "details": "my other test 10"
wolfsage commented 3 years ago

(Note that this affects Test::Routine since Test::Routine wraps everything in one giant subtest)

wolfsage commented 3 years ago

Interestingly, you can get at the output if you specify the job when running yath replay, but it's kinda broken:

alh@emondsfield:~/pobox/git/fm/hm$ yath replay foo.jsonl  -v repro.t
Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
( LAUNCH )  job       repro.t
Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
(  NOTE  )  job       Subtest: all
Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
(  NOTE  )  job       > Subtest: aUse of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 1Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 2Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 3Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 4Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 5Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 6Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 7Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 8Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 9Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my test 10Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PLAN  ]  job       > > Expected assertions: 10Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       + aUse of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
(  NOTE  )  job       > Subtest: bUse of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 1Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 2Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 3Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 4Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 5Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 6Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 7Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 8Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 9Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
[  PASS  ]  job       > + my other test 10Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
( TIMEOUT)  job       Test2::Harness checks for timeouts at a configurable interval, if a test does
( TIMEOUT)  job       not produce any output to stdout or stderr between intervals it will be
( TIMEOUT)  job       forcefully killed under the assumption it has hung. See the '--event-timeout'
( TIMEOUT)  job       option to configure the interval.
< TIMEOUT>  job       A timeout (event) has occured (after 3.0328 seconds), job was forcefully killed
Use of uninitialized value $len in numeric gt (>) at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 522, <$fh> line 32.
Use of uninitialized value $name in sprintf at /home/alh/.plenv/versions/5.24.2/lib/perl5/site_perl/5.24.2/Test2/Formatter/Test2.pm line 529, <$fh> line 32.
( FAILED )  job       repro.t
(  TIME  )  job       Startup: 0.03052s | Events: 0.00000s | Cleanup: 3.00533s | Total: 3.03585s
< REASON >  job       Test script returned error (Signal: 15)
< REASON >  job       Errors were encountered (Count: 1)
< REASON >  job       No plan was declared, and no assertions were made.

The following jobs failed:
+--------------------------------------+-----------+
| Job ID                               | Test File |
+--------------------------------------+-----------+
| 903DE1CA-FAB6-11EB-8007-5D960FBB74F1 | repro.t   |
+--------------------------------------+-----------+

          Yath Result Summary
---------------------------------------
     Fail Count: 1
     File Count: 1
Assertion Count: 21
    -->  Result: FAILED  <--
wolfsage commented 6 months ago

Bumping this one :)

Just hit and rediagnosed it and went to file before noticing I already had!