Re: [BUG] t7030 is flaky

From: SZEDER Gábor <szeder.dev@gmail.com>
Date: Sep 17, 2019, 08:53 UTC
Message-ID: <20190917085325.GG6190@szeder.dev>
In-Reply-To: <20190916235149.GA96478@dentonliu-ltm.internal.salesforce.com>

[Cc-ing brian, because I can vaguely remember (or misremember?) that he cares about GnuPG.]

On Mon, Sep 16, 2019 at 04:51:49PM -0700, Denton Liu wrote:

> I just wanted to report that t7030 is flaky. I first noticed this on
> Szeder's Travis job[1]. I was also able to reproduce this on my Macbook
> with gpg (GnuPG) 2.2.17 and git version 2.23.0.248.g3a9dd8fb08 (latest
> master) by running `./t7030-verify-tag.sh --stress`.

It's not only t7030, but verifying multiple signatures at once in macOS and GnuPG 2.2, i.e. these tests fail occasionally:

  t7030-verify-tag.sh:
    8 - verify multiple tags [2]
    9 - verify multiple tags x509 [1]

  t7004-tag.sh:
    92 - verifying two signed tags in one command should succeed [3]
         (nowadays it's the 94th test)

Note that these are all about tags; as far as I can tell we have no tests that verify multiple signed commits at once.

I tried to reproduce it on Linux, with GnuPG v1.4 and v2.2, no luck so far.

> I'll try to investigate later but for now but at the bottom of this
> email is the trace I obtained.
> 
> [1]: https://travis-ci.org/szeder/git-cooking-topics-for-travis-ci/jobs/518540359

[2] https://travis-ci.org/szeder/git-cooking-topics-for-travis-ci/jobs/514969530#L3183 [3] https://travis-ci.org/szeder/git-cooking-topics-for-travis-ci/jobs/487665767#L3891

Show 6 quoted lines

> expecting success of 7030.9 'verify multiple tags x509': 
> 	tags="seventh-signed nineth-signed-x509" &&
> 	for i in $tags
> 	do
> 		git verify-tag -v --raw $i || return 1
> 	done >expect.stdout 2>expect.stderr.1 &&

Sidenote: oh, look, a shell loop with its standard error redirected to
a file.  Normally we shouldn't do that, because with '-x' tracing it
records the trace output of the commands executed inside the loop as
well.  Luckily, in this case it's not a big issue, because:

> 	grep "^.GNUPG:." <expect.stderr.1 >expect.stderr &&

this 'grep' throws away all that trace, so it doesn't interfere with the test's correctness.

Show 23 quoted lines

> 	git verify-tag -v --raw $tags >actual.stdout 2>actual.stderr.1 &&
> 	grep "^.GNUPG:." <actual.stderr.1 >actual.stderr &&
> 	test_cmp expect.stdout actual.stdout &&
> 	test_cmp expect.stderr actual.stderr
> 
> ++ tags='seventh-signed nineth-signed-x509'
> ++ grep '^.GNUPG:.'
> ++ git verify-tag -v --raw seventh-signed nineth-signed-x509
> ++ grep '^.GNUPG:.'
> ++ test_cmp expect.stdout actual.stdout
> ++ diff -u expect.stdout actual.stdout
> ++ test_cmp expect.stderr actual.stderr
> ++ diff -u expect.stderr actual.stderr
> --- expect.stderr	2019-09-16 23:48:06.000000000 +0000
> +++ actual.stderr	2019-09-16 23:48:06.000000000 +0000
> @@ -8,7 +8,6 @@
>  [GNUPG:] TRUST_ULTIMATE 0 pgp
>  [GNUPG:] NEWSIG
>  [GNUPG:] VERIFICATION_COMPLIANCE_MODE 23
> -[GNUPG:] PROGRESS starting_agent ? 0 0
>  [GNUPG:] GOODSIG F8BF62E0693D0694816377099909C779FA23FD65 /CN=C O Mitter/O=Example/SN=C O/GN=Mitter
>  [GNUPG:] VALIDSIG F8BF62E0693D0694816377099909C779FA23FD65 2019-09-16 20190916T234804 30000101T000000 0 0 1 8 00
>  [GNUPG:] TRUST_FULLY 0 shell

This is interesting, I only remember these tests fail because the 'git verify-tag' command failed. I thought that the error message shown by 'git verify-tag' might give a hint about what went wrong, but 'actual.stderr.1' (i.e. its original stderr) contains this:

  [GNUPG:] NEWSIG committer@example.com
  [GNUPG:] KEY_CONSIDERED 73D758744BE721698EC54E8713B6F51ECDDE430D 0
  [GNUPG:] SIG_ID 2Eg0F1yiJ07HcOjvjO96x2wJvvs 2019-09-17 1568707912
  [GNUPG:] KEY_CONSIDERED 73D758744BE721698EC54E8713B6F51ECDDE430D 0
  [GNUPG:] GOODSIG 13B6F51ECDDE430D C O Mitter <committer@example.com>
  [GNUPG:] VALIDSIG 73D758744BE721698EC54E8713B6F51ECDDE430D 2019-09-17 1568707912 0 4 0 17 2 00 73D758744BE721698EC54E8713B6F51ECDDE430D
  [GNUPG:] KEY_CONSIDERED 73D758744BE721698EC54E8713B6F51ECDDE430D 0
  [GNUPG:] TRUST_ULTIMATE 0 pgp
  [GNUPG:] NEWSIG
  [GNUPG:] VERIFICATION_COMPLIANCE_MODE 23
  [GNUPG:] PROGRESS starting_agent ? 0 0
  [GNUPG:] GOODSIG F8BF62E0693D0694816377099909C779FA23FD65 /CN=C O Mitter/O=Example/SN=C O/GN=Mitter
  [GNUPG:] VALIDSIG F8BF62E0693D0694816377099909C779FA23FD65 2019-09-17 20190917T081152 30000101T000000 0 0 1 8 00
  [GNUPG:] TRUST_FULLY 0 shell

IOW no error message from 'git verify-tag' itself whatsoever, only output from GnuPG, which, to my untrained eyes, looks OK.

Show 14 quoted lines

> error: last command exited with $?=1
> not ok 9 - verify multiple tags x509
> #	
> #		tags="seventh-signed nineth-signed-x509" &&
> #		for i in $tags
> #		do
> #			git verify-tag -v --raw $i || return 1
> #		done >expect.stdout 2>expect.stderr.1 &&
> #		grep "^.GNUPG:." <expect.stderr.1 >expect.stderr &&
> #		git verify-tag -v --raw $tags >actual.stdout 2>actual.stderr.1 &&
> #		grep "^.GNUPG:." <actual.stderr.1 >actual.stderr &&
> #		test_cmp expect.stdout actual.stdout &&
> #		test_cmp expect.stderr actual.stderr
> #