Re: [PATCH] Make some commit hashes in tests reproducible

"Han-Wen Nienhuys via GitGitGadget" [off-list ref] writes:

From: Han-Wen Nienhuys <redacted>

Adds test_tick to t5801-remote-helpers.sh and t3203-branch-output.sh

That can be read from the patch.  Also the subject tells us a half
of what you want to achieve with this change (by the way, your
subject is malformatted and lacks the <area>: prefix; perhaps
"[PATCH] tests: make commit object names reproducible" or something),
but the readers are left hanging without knowing what motivated the
change.  Do any test pieces in these scripts change their behaviour
based on what exact object names are assigned to them, making them
flaky and hard to test, and if so which one and in what way?

Thanks.

On Tue, Jul 07, 2020 at 12:50:33PM -0700, Junio C Hamano wrote:

"Han-Wen Nienhuys via GitGitGadget" [off-list ref] writes:

quoted

From: Han-Wen Nienhuys <redacted>

Adds test_tick to t5801-remote-helpers.sh and t3203-branch-output.sh

That can be read from the patch.  Also the subject tells us a half
of what you want to achieve with this change (by the way, your
subject is malformatted and lacks the <area>: prefix; perhaps
"[PATCH] tests: make commit object names reproducible" or something),
but the readers are left hanging without knowing what motivated the
change.  Do any test pieces in these scripts change their behaviour
based on what exact object names are assigned to them, making them
flaky and hard to test, and if so which one and in what way?

I agree that more discussion would be nice.

But I kind of wonder if we should be aiming for more determinism in
general, just to make debugging and reproduction simpler.

I.e., rather than pointing to _these_ tests, I think we could make an
argument for setting up a known timestamp in the test environment.
test_tick would continue to tick forward as usual, but for any tests
that don't use it, they'd by default get a deterministic outcome.

Something like this:

diff --git a/t/test-lib.sh b/t/test-lib.sh
index 618a7c8d5b..d8adf5a199 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh

@@ -441,15 +441,18 @@ TEST_AUTHOR_LOCALNAME=author
 TEST_AUTHOR_DOMAIN=example.com
 GIT_AUTHOR_EMAIL=${TEST_AUTHOR_LOCALNAME}@${TEST_AUTHOR_DOMAIN}
 GIT_AUTHOR_NAME='A U Thor'
+GIT_AUTHOR_DATE='1112911993 -0700'
 TEST_COMMITTER_LOCALNAME=committer
 TEST_COMMITTER_DOMAIN=example.com
 GIT_COMMITTER_EMAIL=${TEST_COMMITTER_LOCALNAME}@${TEST_COMMITTER_DOMAIN}
 GIT_COMMITTER_NAME='C O Mitter'
+GIT_COMMITTER_DATE='1112911993 -0700'
 GIT_MERGE_VERBOSITY=5
 GIT_MERGE_AUTOEDIT=no
 export GIT_MERGE_VERBOSITY GIT_MERGE_AUTOEDIT
 export GIT_AUTHOR_EMAIL GIT_AUTHOR_NAME
 export GIT_COMMITTER_EMAIL GIT_COMMITTER_NAME
+export GIT_COMMITTER_DATE GIT_AUTHOR_DATE
 export EDITOR
 
 # Tests using GIT_TRACE typically don't want <timestamp> <file>:<line> output

That's using the same start point as test_tick, though really it could
be anything. I've intentionally _not_ called test_tick at the beginning
of each script, because that would throw off all of the scripts that do
use it by one tick (whereas the first test_tick will overwrite these
values).

Trying to devil's advocate against this line of reasoning:

  - using the current timestamp introduces more randomness into the test
    suite, which could uncover problems. I'm somewhat skeptical, as the
    usual outcome I see here is that we realize a test's expected output
    is simply racy, and we remove the raciness by using test_tick

  - using the current timestamp could alert us to problems that occur
    only as the clock ticks forward (e.g., if we had a Y2021 bug, we'd
    notice when the clock rolled forward).

  - some tests may rely on having a "recent" timestamp in commits (e.g.,
    when looking at relative date handling). I think all of the
    relative-time tests already use a specific date, though, because
    otherwise we have too many problems with raciness.

Note that the patch above does seem to cause two tests to fail. One of
them I _suspect_ is a raciness problem (order of commits output changes,
which implies the original was expecting the time to increment between
two commits without running test_tick). And the other looks like some
weird interaction with the perl test harness. I'd be happy to dig into
both if this direction seems sane.

-Peff

On Tue, Jul 07, 2020 at 04:54:18PM -0400, Jeff King wrote:

Note that the patch above does seem to cause two tests to fail. One of
them I _suspect_ is a raciness problem (order of commits output changes,
which implies the original was expecting the time to increment between
two commits without running test_tick).

It turns out this does depend on the system clock, but isn't racy in the
traditional sense. See the explanation below (which might be worth doing
even if we don't switch to a deterministic time everywhere else).

-- >8 --
Subject: [PATCH] t6000: use test_tick consistently

The first two commits created in t6000 are done without test_tick,
meaning they use the current system clock. After that, we create one
with test_tick, which means it uses a deterministic time in the past.

The result of the "symleft flag bit is propagated down from tag" test
relies on the output order of commits from git-log, which in turn
depends on these timestamps. So this test is technically dependent on
the system clock time, though in practice it would only matter if your
system clock was set before test_tick's default time (which is in 2005).

However, let's use test_tick consistently for those early commits (and
update the expected output to match). This makes the test deterministic,
which is in turn easier to reason about and debug.

Note that there's also a fourth commit here, and it does not use
test_tick. It does have a deterministic timestamp because of the prior
use of test_tick in the script, but it will always be the same time as
the third commit. Let's use test_tick here, too, for consistency.  The
matching timestamps between the third and fourth commit are not an
important part of the test.

We could also use test_commit in all of these cases, as it runs
test_tick under the hood. But it would be awkward to do so, as these
tests diverge from the usual test_commit patterns (e.g., by creating
multiple files in a single commit).

Signed-off-by: Jeff King <redacted>
---
 t/t6000-rev-list-misc.sh | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/t/t6000-rev-list-misc.sh b/t/t6000-rev-list-misc.sh
index 3dc1ad8f71..3bb0e4ff8f 100755
--- a/t/t6000-rev-list-misc.sh
+++ b/t/t6000-rev-list-misc.sh

@@ -8,6 +8,7 @@ test_expect_success setup '
 	echo content1 >wanted_file &&
 	echo content2 >unwanted_file &&
 	git add wanted_file unwanted_file &&
+	test_tick &&
 	git commit -m one
 '
 

@@ -21,6 +22,7 @@ test_expect_success 'rev-list --objects with pathspecs and deeper paths' '
 	mkdir foo &&
 	>foo/file &&
 	git add foo/file &&
+	test_tick &&
 	git commit -m two &&
 
 	git rev-list --objects HEAD -- foo >output &&

@@ -69,6 +71,7 @@ test_expect_success '--no-object-names and --object-names are last-one-wins' '
 '
 
 test_expect_success 'rev-list A..B and rev-list ^A B are the same' '
+	test_tick &&
 	git commit --allow-empty -m another &&
 	git tag -a -m "annotated" v1.0 &&
 	git rev-list --objects ^v1.0^ v1.0 >expect &&

@@ -84,10 +87,10 @@ test_expect_success 'propagate uninteresting flag down correctly' '
 test_expect_success 'symleft flag bit is propagated down from tag' '
 	git log --format="%m %s" --left-right v1.0...master >actual &&
 	cat >expect <<-\EOF &&
-	> two
-	> one
 	< another
 	< that
+	> two
+	> one
 	EOF
 	test_cmp expect actual
 '

-- 
2.27.0.730.gcc195a083d

On Tue, Jul 7, 2020 at 9:50 PM Junio C Hamano [off-list ref] wrote:

"Han-Wen Nienhuys via GitGitGadget" [off-list ref] writes:

quoted

From: Han-Wen Nienhuys <redacted>

Adds test_tick to t5801-remote-helpers.sh and t3203-branch-output.sh

That can be read from the patch.  Also the subject tells us a half
of what you want to achieve with this change (by the way, your
subject is malformatted and lacks the <area>: prefix; perhaps
"[PATCH] tests: make commit object names reproducible" or something),
but the readers are left hanging without knowing what motivated the
change.  Do any test pieces in these scripts change their behaviour
based on what exact object names are assigned to them, making them
flaky and hard to test, and if so which one and in what way?

You're right, I forgot to provide a piece of the puzzle. These tests
have been failing either legitimately or flakily with reftable.

I built a GIT_DEBUG_REFS functionality, which dumps ref backend
interactions onto stderr. This should be reworked to use the tracing
functionality, but you can look at the patch in my reftable series.

When a test fails with reftable, the easiest way to debug is running
it both with and without GIT_DEBUG_REFS=1, and running a diff on the
output.

This needs the commit SHA1s to be deterministic, or the SHA1s will
generate spurious diffs.

I agree with Jeff, that a more structural approach to making sha1s
deterministic would be preferable.

-- 
Han-Wen Nienhuys - Google Munich
I work 80%. Don't expect answers from me on Fridays.
--
Google Germany GmbH, Erika-Mann-Strasse 33, 80636 Munich
Registergericht und -nummer: Hamburg, HRB 86891
Sitz der Gesellschaft: Hamburg
Geschäftsführer: Paul Manicle, Halimah DeLaine Prado