Selftests fail with "make check" but succeed with "./test.sh" and direct executions of "t/*.t" programs

jimklimov commented 4 years ago

Console log of make check ends with:

Test Summary Report
-------------------
t/znapzend.t     (Wstat: 0 Tests: 51 Failed: 2)
  Failed tests:  49, 49
  Parse errors: Tests out of sequence.  Found (48) but expected (49)
                Plan (1..48) must be at the beginning or end of the TAP output
                Tests out of sequence.  Found (49) but expected (50)
                More than one plan found in TAP output
                Tests out of sequence.  Found (49) but expected (51)
Displayed the first 5 of 7 TAP syntax errors.
Re-run prove with the -p option to see them all.
t/znapzendzetup.t (Wstat: 0 Tests: 62 Failed: 0)
  Parse errors: Tests out of sequence.  Found (7) but expected (4)
                Tests out of sequence.  Found (8) but expected (5)
                Tests out of sequence.  Found (9) but expected (6)
                Tests out of sequence.  Found (10) but expected (7)
                Tests out of sequence.  Found (11) but expected (8)
Displayed the first 5 of 60 TAP syntax errors.
Re-run prove with the -p option to see them all.
Files=4, Tests=126, 344 wallclock secs ( 0.40 usr  0.35 sys + 128.90 cusr 95.65 csys = 225.30 CPU)
Result: FAIL
Failed 2/4 test programs. 2/126 subtests failed.
make: *** [Makefile:956: check] Error 255

Nothing apparent pops up in the megabyte of logs as to what failed, so looking deeper...

jimklimov commented 4 years ago

A few suspicious gems from the pile of rubble:

t/znapzend.t .......
Failed -1/48 subtests
Possible attempt to separate words with commas at t/znapzendzetup.t line 143.

failed to destroy mock dataset(s)

UPDATE: This is seen in successful runs too, same amount of times

failed to list mock dataset(s)

UPDATE: This is seen in successful runs too, same amount of times

t/znapzendzetup.t ..
Failed 3/65 subtests
t/znapzendztatz.t .. ok

Overall, the fails map "adds up" :)

jim@jimoi:~/shared/znapzend$ grep subtes test-1596025693.log 
Failed -1/48 subtests 
Failed 3/65 subtests 
Failed 2/4 test programs. 2/126 subtests failed.

jimklimov commented 4 years ago

make check runs:

/usr/bin/perl -Ithirdparty/lib/perl5 "-MExtUtils::Command::MM" "-e" "test_harness(0, 'lib','thirdparty/lib/perl5')" t/*.t

./test.sh runs:

perl -I./thirdparty/lib/perl5 \
-MDevel::Cover=+ignore,thirdparty ./t/znapzend.t ./bin/znapzend || test $? == 1
perl -I./thirdparty/lib/perl5 \
-MDevel::Cover=+ignore,thirdparty ./t/znapzendzetup.t ./bin/znapzend || test $? == 1
perl -I./thirdparty/lib/perl5 \
-MDevel::Cover=+ignore,thirdparty ./t/znapzendztatz.t ./bin/znapzend || test $? == 1
perl -I./thirdparty/lib/perl5 \
-MDevel::Cover=+ignore,thirdparty ./t/autoscrub.t ./bin/znapzend || test $? == 1

Manual tests just run the ./t/*.t scripts.

The two latter options seem okay...

jimklimov commented 4 years ago

Unfortunately the current tests in make check do not report ok/not ok so it is hard to figure out what the harness dislikes and miscounts.

jimklimov commented 4 years ago

Caught it with test_harness verbosity "1":

        src_plan = 1hour=>10minutes                                                           
        tsformat = %Y-%m-%d-%H%M%S                                                    
Do you want to save this backup set [y/N]? ok 5 - znapzendzetup edit   
*** backup plan: tank/source ***                                                               
           dst_0 = backup/destination                                                            
      dst_0_plan = 1hour=>10minutes,30minutes=>5minutes,10minutes=>60seconds

Benign huh? the "ok 5" above just is not on start of line! (there are no "not ok" results in the test, as expected). Overall:

jim@jimoi:~/shared/znapzend/t$ grep -w ok znapzendzetup.t-1596039280-harness-verbose.log 
ok 1 - use ZnapZend;
ok 2 - znapzendzetup help
ok 3 - znapzendzetup list
Do you want to save this backup set [y/N]? ok 4 - znapzendzetup create
Do you want to save this backup set [y/N]? ok 5 - znapzendzetup edit
Do you want to save this backup set [y/N]? ok 6 - znapzendzetup edit src_dataset
ok 7 - znapzendzetup create --donotask
ok 8 - znapzendzetup edit --donotask
...

and here we go missing 3 of expected test results, finishing 62 of 65 and getting Parse errors: Tests out of sequence. Found (7) but expected (4) et al.

jimklimov commented 4 years ago

The tests of znapzend.t itself fail in last few steps with daemonization - apparently both codepaths end up okay and print their (same) verdict, confusing the harness:

pre znap command for dst_0
ok 45 - znapzend --inherited --recursive --features=zfsGetType --runonce=tank/source/child succeeds with new ZFS when it lists snapshots
ok 46 - znapzend --features=zfsGetType --runonce=tank/source fails with old ZFS when it lists snapshots
pre znap command for dst_0
pre znap command for dst_0
pre znap command for dst_0
post znap command for dst_0
post znap command for dst_0
post znap command for dst_0
pre znap command
post znap command
pre znap command for dst_0
pre znap command
post znap command
pre znap command
post znap command
pre znap command for dst_0
pre znap command
post znap command
pre znap command for dst_0
post znap command for dst_0
...

### AND HERE GOES:

ok 47 - znapzend --daemonize \#1
ok 47 - znapzend --daemonize \#1
1..47
ok 48 - znapzend --daemonize \#2
1..48
ok 48 - znapzend --daemonize \#2
ok 49 - znapzend --daemonize \#3
1..49
ok 49 - znapzend --daemonize \#3
1..49
Failed -1/47 subtests 

Test Summary Report
-------------------
t/znapzend.t (Wstat: 0 Tests: 52 Failed: 4)
  Failed tests:  48, 48-49, 49
  Parse errors: Tests out of sequence.  Found (47) but expected (48)
                Plan (1..47) must be at the beginning or end of the TAP output
                Tests out of sequence.  Found (48) but expected (49)
                More than one plan found in TAP output
                Tests out of sequence.  Found (48) but expected (50)
Displayed the first 5 of 10 TAP syntax errors.
Re-run prove with the -p option to see them all.
Files=1, Tests=52, 254 wallclock secs ( 0.23 usr  0.29 sys + 69.94 cusr 48.55 csys = 119.01 CPU)
Result: FAIL
Failed 1/1 test programs. 4/52 subtests failed.

The actual code behind these may even come from me, but with poor understanding of harness, it seems:

# Do not test after daemonize, to avoid conflicts
is (runCommand_canThrow(qw(--daemonize --debug),'--features=oracleMode,recvu',
    qw(--pidfile=znapzend.pid)), 1, 'znapzend --daemonize #1');
#...but do try to cover these error codepaths ;)
eval { is (runCommand_canThrow(qw(--daemonize --debug),'--features=compressed',
    qw(--pidfile=znapzend2.pid)), 1, 'znapzend --daemonize #2'); };
eval { is (runCommand_canThrow(qw(--daemonize --debug),'-n',
    qw(--pidfile=znapzend.pid)), 1, 'znapzend --daemonize #3'); };

done_testing;

1;

So on one hand, maybe the eval blocks hide the amount of tests the harness expects, on another I'm not sure (and it is not commented) if two tests use same PID file name intentionally for codepathing, or by oversight, and whether daemonization really happens in test context and how that all behaves.

jimklimov commented 3 years ago

Note: with PR #512 the README would also reference this problem (in commit https://github.com/oetiker/znapzend/pull/512/commits/f3069067bca6f067784539ff8459f61e844773dd). That paragraph would need to be removed after rectifying this completely.

jimklimov commented 3 years ago

Wanted to close this after #517 and found the note about README note :\

oetiker / znapzend

Selftests fail with "make check" but succeed with "./test.sh" and direct executions of "t/*.t" programs #500