t/11-wmk.t often fails at test 3 due to only full second resolution of perl's stat()

[xtaran]

t/11-wmk.t often fails as follows:

→ env WML='/usr/bin/wml -q -W1,-N' prove -I. t/11-wmk.t
t/11-wmk.t .. "my" variable $tmpfile1 masks earlier declaration in same scope at t/11-wmk.t line 73.
t/11-wmk.t .. ok   
All tests successful.
Files=1, Tests=7,  1 wallclock secs ( 0.02 usr  0.00 sys +  1.10 cusr  0.18 csys =  1.30 CPU)
Result: PASS
→ env WML='/usr/bin/wml -q -W1,-N' prove -I. t/11-wmk.t
t/11-wmk.t .. "my" variable $tmpfile1 masks earlier declaration in same scope at t/11-wmk.t line 73.
t/11-wmk.t .. 3/7 
#   Failed test at t/11-wmk.t line 57.
#          got: '/usr/bin/wml -q -W1,-N -n -q -W "1,-N" -o a.html a.wml
# '
#     expected: '/usr/bin/wml -q -W1,-N -n -q -W "1,-N" -o a.html a.wml  (skipped)
# '
# Looks like you failed 1 test of 7.
t/11-wmk.t .. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/7 subtests 

Test Summary Report
-------------------
t/11-wmk.t (Wstat: 256 Tests: 7 Failed: 1)
  Failed test:  3
  Non-zero exit status: 1
Files=1, Tests=7,  1 wallclock secs ( 0.02 usr  0.00 sys +  1.19 cusr  0.22 csys =  1.43 CPU)
Result: FAIL

It seems that wmk isn't really able to recognize a difference for very short time intervals, i.e. if wmk is called two times immediately after a file has been created, it will not consider it to be skipped:

→ echo ' ' > a.wml; while :; do wmk -q -W1,-N; done
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml  (skipped)
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml  (skipped)
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml  (skipped)
[…]

What helped was a sleep 1 between creating the file and running wmk:

→ echo ' ' > a.wml; sleep 1; while :; do wmk -q -W1,-N; done
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml  (skipped)
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml  (skipped)
/usr/bin/wml -n -q -W "1,-N" -o a.html a.wml  (skipped)

But that would only be a workaround to get the test suite not failing and ignores the underlying issue. Which is that perl's stat() returns the mtime only in full seconds. So as long as the mtime of a.wml and a.html have the same full second, wmk will consider a rebuild:

→ echo ' ' > a.wml; for i in 1 2 3 4 ; do wmk ; ls --full-time a.wml a.html ; done
/usr/bin/wml -n -o a.html a.wml
-rw-r--r-- 1 abe abe 0 2018-12-27 02:37:08.537852467 +0100 a.html
-rw-r--r-- 1 abe abe 2 2018-12-27 02:37:08.229853531 +0100 a.wml
/usr/bin/wml -n -o a.html a.wml
-rw-r--r-- 1 abe abe 0 2018-12-27 02:37:08.861851349 +0100 a.html
-rw-r--r-- 1 abe abe 2 2018-12-27 02:37:08.229853531 +0100 a.wml
/usr/bin/wml -n -o a.html a.wml
-rw-r--r-- 1 abe abe 0 2018-12-27 02:37:09.185850230 +0100 a.html
-rw-r--r-- 1 abe abe 2 2018-12-27 02:37:08.229853531 +0100 a.wml
/usr/bin/wml -n -o a.html a.wml  (skipped)
-rw-r--r-- 1 abe abe 0 2018-12-27 02:37:09.185850230 +0100 a.html
-rw-r--r-- 1 abe abe 2 2018-12-27 02:37:08.229853531 +0100 a.wml

The proper solution would be to use Time::HiRes::stat() (and Time::HiRes is in Perl's list of core modules), but then again, is it really that important. IMHO the way the test suite currently tests things, it's testing a corner case, which has no real impact to the real world and that sleep(1) in the test wouldn't hurt anyone. Then again the proper solution with Time::HiRes shouldn't hurt either.

So you have two choices to fix this issue:

• add use Time::HiRes qw(stat); to wmk.src, or
• add sleep(1); between creating the temporary files and running the first test.

(I also assume this and #10 are the reason why t/11-wmk.t is not run by run_tests.pl. So once this is fixed, it could be added to run_tests.pl.)

[xtaran]

This is probably also the real cause and fix for this Debian bug report which back then made me disable t/11-wmk.t in Debian, too.

[shlomif]

Should be fixed in git master.

[shlomif]

Thanks!