t1092: use GIT_PROGRESS_DELAY for consistent results

[derrickstolee]

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

Thanks,
-Stolee

cc: gitster@pobox.com
cc: stolee@gmail.com
cc: Jonathan Nieder jrnieder@gmail.com
cc: Taylor Blau me@ttaylorr.com
cc: Ævar Arnfjörð Bjarmason avarab@gmail.com

[derrickstolee]

/submit

[gitgitgadget]

Submitted as pull.960.git.1621886108515.gitgitgadget@gmail.com

To fetch this version into FETCH_HEAD:

git fetch https://github.com/gitgitgadget/git pr-960/derrickstolee/sparse-index/progress-fix-v1

To fetch this version to local tag pr-960/derrickstolee/sparse-index/progress-fix-v1:

git fetch --no-tags https://github.com/gitgitgadget/git tag pr-960/derrickstolee/sparse-index/progress-fix-v1

[gitgitgadget]

On the Git mailing list, Jonathan Nieder wrote (reply to this):

Hi,

Derrick Stolee wrote:

> 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.

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

[gitgitgadget]

User Jonathan Nieder <jrnieder@gmail.com> has been added to the cc: list.

[gitgitgadget]

On the Git mailing list, Derrick Stolee wrote (reply to this):

On 5/24/21 4:28 PM, Jonathan Nieder wrote:
> Hi,
> 
> Derrick Stolee wrote:
> 
>> 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.
> 
> 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?

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 

[gitgitgadget]

On the Git mailing list, Taylor Blau wrote (reply to this):

On Mon, May 24, 2021 at 04:38:18PM -0400, Derrick Stolee wrote:
> On 5/24/21 4:28 PM, Jonathan Nieder wrote:
> > 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.
>
> 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.

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

[gitgitgadget]

User Taylor Blau <me@ttaylorr.com> has been added to the cc: list.

[gitgitgadget]

On the Git mailing list, Ævar Arnfjörð Bjarmason wrote (reply to this):

On Mon, May 24 2021, Taylor Blau wrote:

> On Mon, May 24, 2021 at 04:38:18PM -0400, Derrick Stolee wrote:
>> On 5/24/21 4:28 PM, Jonathan Nieder wrote:
>> > 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.
>>
>> 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.
>
> 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.

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.

> 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

[gitgitgadget]

User Ævar Arnfjörð Bjarmason <avarab@gmail.com> has been added to the cc: list.

[gitgitgadget]

On the Git mailing list, Taylor Blau wrote (reply to this):

On Tue, May 25, 2021 at 12:57:52AM +0200, Ævar Arnfjörð Bjarmason wrote:
> On Mon, May 24 2021, Taylor Blau wrote:
>
> > 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.
>
> I don't see why we wouldn't just tweak GIT_PROGRESS_DELAY to support -1
> or something for "inf".

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

[gitgitgadget]

On the Git mailing list, Derrick Stolee wrote (reply to this):

On 5/24/2021 8:13 PM, Taylor Blau wrote:
> On Tue, May 25, 2021 at 12:57:52AM +0200, Ævar Arnfjörð Bjarmason wrote:
>> On Mon, May 24 2021, Taylor Blau wrote:
>>
>>> 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.
>>
>> I don't see why we wouldn't just tweak GIT_PROGRESS_DELAY to support -1
>> or something for "inf".
> 
> 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.

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

Thanks,
-Stolee

[gitgitgadget]

On the Git mailing list, Junio C Hamano wrote (reply to this):

Derrick Stolee <stolee@gmail.com> writes:

> 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.

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.

[gitgitgadget]

On the Git mailing list, Junio C Hamano wrote (reply to this):

Taylor Blau <me@ttaylorr.com> writes:

> 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?

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.

[gitgitgadget]

On the Git mailing list, Junio C Hamano wrote (reply to this):

Taylor Blau <me@ttaylorr.com> writes:

> On Tue, May 25, 2021 at 12:57:52AM +0200, Ævar Arnfjörð Bjarmason wrote:
>> On Mon, May 24 2021, Taylor Blau wrote:
>>
>> > 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.
>>
>> I don't see why we wouldn't just tweak GIT_PROGRESS_DELAY to support -1
>> or something for "inf".
>
> 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.

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?

[gitgitgadget]

On the Git mailing list, Junio C Hamano wrote (reply to this):

Derrick Stolee <stolee@gmail.com> writes:

>> So we silently convert -1 to 2^64-1, and call it a day.
>
> That works for me. I'll send a v2 with that tomorrow unless someone
> presents a better option.

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 <dstolee@microsoft.com>
         Signed-off-by: Junio C Hamano <gitster@pobox.com>
    @@ 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 "$@"
      }

[gitgitgadget]

This branch is now known as ds/t1092-fix-flake-from-progress.

[gitgitgadget]

This patch series was integrated into seen via git@0126713.

[gitgitgadget]

On the Git mailing list, Ævar Arnfjörð Bjarmason wrote (reply to this):

On Mon, May 24 2021, Taylor Blau wrote:

> On Tue, May 25, 2021 at 12:57:52AM +0200, Ævar Arnfjörð Bjarmason wrote:
>> On Mon, May 24 2021, Taylor Blau wrote:
>>
>> > 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.
>>
>> I don't see why we wouldn't just tweak GIT_PROGRESS_DELAY to support -1
>> or something for "inf".
>
> 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.

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:

diff --git a/progress.c b/progress.c
index 680c6a8bf93..191c62cbbfb 100644
--- a/progress.c
+++ b/progress.c
@@ -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.

[gitgitgadget]

On the Git mailing list, Junio C Hamano wrote (reply to this):

Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes:

> 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:

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.

[gitgitgadget]

On the Git mailing list, Derrick Stolee wrote (reply to this):

On 5/25/2021 2:32 AM, Junio C Hamano wrote:
> Derrick Stolee <stolee@gmail.com> writes:
> 
>>> So we silently convert -1 to 2^64-1, and call it a day.
>>
>> That works for me. I'll send a v2 with that tomorrow unless someone
>> presents a better option.
> 
> 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 <dstolee@microsoft.com>
>          Signed-off-by: Junio C Hamano <gitster@pobox.com>
>     @@ 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 "$@"
>       }

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/036b01d750ed$642b75c0$2c826140$@nexbridge.com/

Thanks,
-Stolee

[gitgitgadget]

On the Git mailing list, Taylor Blau wrote (reply to this):

On Tue, May 25, 2021 at 11:54:56AM +0900, Junio C Hamano wrote:
> 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 found this while responding to Randall (who is observing the same
problem in another thread):

  https://lore.kernel.org/git/YK0TKVZidW%2FG8XBr@nand.local/

Thanks,
Taylor

[gitgitgadget]

This patch series was integrated into seen via git@5353924.

[gitgitgadget]

This patch series was integrated into next via git@3a1982b.

[gitgitgadget]

On the Git mailing list, Junio C Hamano wrote (reply to this):

Derrick Stolee <stolee@gmail.com> writes:

> On 5/25/2021 2:32 AM, Junio C Hamano wrote:
>> Derrick Stolee <stolee@gmail.com> writes:
>> 
>>>> So we silently convert -1 to 2^64-1, and call it a day.
>>>
>>> That works for me. I'll send a v2 with that tomorrow unless someone
>>> presents a better option.
>> 
>> I'll queue with this tweak for tonight's integration run.
>> 
>> ...
> 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/036b01d750ed$642b75c0$2c826140$@nexbridge.com/

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.

[gitgitgadget]

On the Git mailing list, Junio C Hamano wrote (reply to this):

Junio C Hamano <gitster@pobox.com> writes:

> 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?

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.

[gitgitgadget]

On the Git mailing list, Taylor Blau wrote (reply to this):

On Wed, May 26, 2021 at 05:46:16AM +0900, Junio C Hamano wrote:
> 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. 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