t1092: use GIT_PROGRESS_DELAY for consistent results

From: Derrick Stolee <[email protected]>

The t1092-sparse-checkout-compatibility.sh tests compare the stdout and stderr for several Git commands across both full checkouts, sparse checkouts with a full index, and sparse checkouts with a sparse index. Since these are direct comparisons, sometimes a progress indicator can flush at unpredictable points, especially on slower machines. This causes the tests to be flaky.

One standard way to avoid this is to add GIT_PROGRESS_DELAY=0 to the Git commands that are run, as this will force every progress indicator created with start_progress_delay() to be created immediately. However, there are some progress indicators that are created in the case of a full index that are not created with a sparse index. Moreover, their values may be different as those indexes have a different number of entries.

Instead, use GIT_PROGRESS_DELAY=100000 to ensure that any reasonable machine running these tests would never display delayed progress indicators.

---
t1092: use GIT_PROGRESS_DELAY for consistent results

We found this while running PR builds in microsoft/git.

Thanks, -Stolee

Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-960%2Fderrickstolee%2Fsparse-index%2Fprogress-fix-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-960/derrickstolee/sparse-index/progress-fix-v1
Pull-Request: https://github.com/gitgitgadget/git/pull/960

 t/t1092-sparse-checkout-compatibility.sh | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

index 12e6c453024f..e9a815ca7aaa 100755
@@ -106,18 +106,18 @@ init_repos () {
 run_on_sparse () {
 	(
 		cd sparse-checkout &&
-		"$@" >../sparse-checkout-out 2>../sparse-checkout-err
+		GIT_PROGRESS_DELAY=100000 "$@" >../sparse-checkout-out 2>../sparse-checkout-err
 	) &&
 	(
 		cd sparse-index &&
-		"$@" >../sparse-index-out 2>../sparse-index-err
+		GIT_PROGRESS_DELAY=100000 "$@" >../sparse-index-out 2>../sparse-index-err
 	)
 }
 
 run_on_all () {
 	(
 		cd full-checkout &&
-		"$@" >../full-checkout-out 2>../full-checkout-err
+		GIT_PROGRESS_DELAY=100000 "$@" >../full-checkout-out 2>../full-checkout-err
 	) &&
 	run_on_sparse "$@"
 }

base-commit: de88ac70f3a801262eb3aa087e5d9a712be0a54a

gitgitgadget

Hi,

Hm, I think this test strategy is going to be fundamentally flaky
regardless: Git doesn't intend to guarantee any kind of stability in the exact stderr output it writes.

Could the tests be made to check more semantically meaningful information such as "git ls-files -s" output instead?

Thanks,
Jonathan

The test is comparing the same exact Git command just with different configurations. Any change to what Git writes to stderr should be consistent across these, unless there is an explicit reason why it would behave differently across these options (for example, saying "You are in a sparse checkout" in 'git status').

There are no expectations that stderr is stable across versions of Git. These tests don't add friction to developers making new features or changing the error messages that appear over stderr. It's just that these tests should catch any unintended inconsistency across these modes.

Thanks,
-Stolee

I agree with Stolee that these tests are valuable for asserting that output is the consistent whether or not you are using the sparse index.

I find setting GIT_PROGRESS_DELAY to a large number to a be a little ugly, but there isn't an apparent better way to accomplish the same thing. Of course, it would be nice to have an environment variable to specify where progress meters are written to, or a global option to disable progress meters altogether.

But I don't think this isolated instance should push in the direction of adding support for either of the above, regardless of how easy it might be.

What would perhaps make more sense is to silence the progress meters from the commands themselves. AFAICT the only command called by run_on_sparse() which generates a progress meter is 'git checkout', 'git merge', and 'git submodule', all of which support '--no-progress'. Might it be worth passing that option instead of setting GIT_PROGRESS_DELAY to a large value?

(For what it's worth, I have no strong opinion either way, so I would be happy to attach my Reviewed-by to even the current version of this patch).

Thanks,
Taylor

I don't see why we wouldn't just tweak GIT_PROGRESS_DELAY to support -1 or something for "inf".

It was added as a one-off (it seems for testing, but made public, so not in the GIT_TEST_* namespace) in 44a4693bfce (progress: create GIT_PROGRESS_DELAY, 2019-11-25).

The progress.c API will already nicely deal with this case if something in start_progress_delay() is made to return NULL if we pass a flag down to it.

Ironically, I think that this already works, since we parse the value of GIT_PROGRESS_DELAY as unsigned, and don't bother checking for if the input is negative (since we eventually call git_parse_unsigned(), which doesn't have any extra checks other than for overflow).

So we silently convert -1 to 2^64-1, and call it a day.

Thanks,
Taylor

That works for me. I'll send a v2 with that tomorrow unless someone presents a better option.

Thanks,
-Stolee

If it just happens that an auto-gc gets triggered, and millions of other similar reasons in the future, will break that expectation, without running two different vintages of Git.

I agree with Jonathan that it fundamentally is flakey to expect two invocations of Git will behave exactly the same. Even repacking a repository starting from exactly the same state into a single pack may not produce byte-for-byte identical result due to thread scheduling.

Yup. The progress meters are obvious source of variation, but there is no guarantee that is the only source of variation. The test strategy to run the same command twice and judge only by observing their stdout and stderr is, eh, suboptimal. If we devise a sequence of commands that are tested immediately followed by a sequence of commands to check the outcome of these commands, and the output from the latter for two runs are the same, then that is a more sensible approach, as the latter "visualize the outcome of the commands that are just tested" can be controlled more tightly to ignore meaningless variations (like progress meters or base-delta paring in a resulting packfile of a parallel packing) and focus on the aspects of the outcome that matter.

Stepping back a bit, this is an unattended test---why do we even see progress meters? Are we forcing the output to tty somehow in our tests, or do some codepaths forget to ask isatty() when the command line does not say --progress or --no-progress?

I'll queue with this tweak for tonight's integration run.

Thanks.

1: d327f7d3b9 ! 1: e2b05746e1 t1092: use GIT_PROGRESS_DELAY for consistent results

    @@ Commit message
         values may be different as those indexes have a different number of
         entries.
     
    -    Instead, use GIT_PROGRESS_DELAY=100000 to ensure that any reasonable
    -    machine running these tests would never display delayed progress
    -    indicators.
    +    Instead, use GIT_PROGRESS_DELAY=-1 (which will turn into UINT_MAX)
    +    to ensure that any reasonable machine running these tests would
    +    never display delayed progress indicators.
     
         Signed-off-by: Derrick Stolee <[email protected]>
         Signed-off-by: Junio C Hamano <[email protected]>
    @@ t/t1092-sparse-checkout-compatibility.sh: init_repos () {
      	(
      		cd sparse-checkout &&
     -		"$@" >../sparse-checkout-out 2>../sparse-checkout-err
    -+		GIT_PROGRESS_DELAY=100000 "$@" >../sparse-checkout-out 2>../sparse-checkout-err
    ++		GIT_PROGRESS_DELAY=-1 "$@" >../sparse-checkout-out 2>../sparse-checkout-err
      	) &&
      	(
      		cd sparse-index &&
     -		"$@" >../sparse-index-out 2>../sparse-index-err
    -+		GIT_PROGRESS_DELAY=100000 "$@" >../sparse-index-out 2>../sparse-index-err
    ++		GIT_PROGRESS_DELAY=-1 "$@" >../sparse-index-out 2>../sparse-index-err
      	)
      }
      
    @@ t/t1092-sparse-checkout-compatibility.sh: init_repos () {
      	(
      		cd full-checkout &&
     -		"$@" >../full-checkout-out 2>../full-checkout-err
    -+		GIT_PROGRESS_DELAY=100000 "$@" >../full-checkout-out 2>../full-checkout-err
    ++		GIT_PROGRESS_DELAY=-1 "$@" >../full-checkout-out 2>../full-checkout-err
      	) &&
      	run_on_sparse "$@"
      }

Well yes, it works in the sense that instead of arbitrary big value for delay we have the biggerest and largerest value we can manage :)

I mean why do just that when we can also do this:

index 680c6a8bf93..191c62cbbfb 100644
@@ -252,7 +252,13 @@ void display_progress(struct progress *progress, uint64_t n)
 static struct progress *start_progress_delay(const char *title, uint64_t total,
 					     unsigned delay, unsigned sparse)
 {
-	struct progress *progress = xmalloc(sizeof(*progress));
+	struct progress *progress;
+
+	/* GIT_PROGRESS_DELAY=-1 */
+	if (delay == (unsigned)-1)
+		return NULL;
+
+	progress = xmalloc(sizeof(*progress));
 	progress->title = title;
 	progress->total = total;
 	progress->last_value = -1;

Which will cause the progress code to abort early in that case, and IMO is less magical if we're going to have this GIT_PROGRESS_DELAY=-1 in the codebase and relying on the wrap-around of -1.

Don't make unnecessary changes before any release. If a breakage can be fixed without risking to introduce any new breakages with code change, postpone such a change and save bandwidth to finding and fixing _other_ regressions.

Thanks.

Thank you for proactively modifying the patch. This works for me. I didn't realize that this was affecting other contributors [1] until I woke up this morning.

[1] https://lore.kernel.org/git/[email protected]/

Thanks,
-Stolee

I found this while responding to Randall (who is observing the same problem in another thread):

https://lore.kernel.org/git/YK0TKVZidW%[email protected]/

Thanks,
Taylor

Well, not so well X-<. It seems that some builds are not happy with this change. See https://github.com/git/git/actions/runs/876229761
specifically these two:

    https://github.com/git/git/runs/2669177395?check_suite_focus=true#step:7:3549
    https://github.com/git/git/runs/2669080101?check_suite_focus=true#step:6:988

I suspect that it has something to do with 32-bit platforms?

Thanks.

Reverting the change that was squashed in seems to do the job.
https://github.com/git/git/actions/runs/876338380 is labelled as 'seen' but it is 'next' that failed in the message I am responding to plus the revert of s/=100000/=-1/g.

Let's queue the 100000 version for now and get the =inf patch applied after the release.

Thanks.

Thanks. Of course, redirecting stderr into a file and halting after we get a non-zero exit code makes this pretty hard to debug from that output alone, but this is pretty easily reproducible on a 32-bit Docker image:

    root@99cfe0d56673:/git-master# getconf LONG_BIT
    32
    root@99cfe0d56673:/git-master# GIT_PROGRESS_DELAY=-1 ./bin-wrappers/git status
    fatal: failed to parse GIT_PROGRESS_DELAY

Looking more closely in a debugger shows that we're failing because of this check in 'config.c:git_parse_unsigned()':

    if (unsigned_mult_overflows(factor, val) ||
        factor * val > max) {
          errno = ERANGE;
          return 0;
    }

unsigned_mult_overflows() doesn't trigger regardless of architecture, since even though val is large, factor is 1, so factor * val == val. But val is much larger than max, so we fail there. 'max' is just 'maximum_unsigned_value_of_type(long)', or 2^32-1, while val is 2^64-1.

Thanks,
Taylor