Is MacOS CI flaky?

Is MacOS CI flaky?

[Glen Choo]

1. https://github.com/chooglen/git/actions/runs/5294136258

is just

2. https://github.com/chooglen/git/actions/runs/5292953535

with a fix for "win build", but 2. also failed for completely unrelated
reasons on osx-*.

Casually clicking through https://github.com/git/git/actions/ suggests
that others might be experiencing similar failures too?

- https://github.com/git/git/actions/runs/5293250265
- https://github.com/git/git/actions/runs/5289074140

Re: Is MacOS CI flaky?

[Junio C Hamano]

Glen Choo <chooglen@google.com> writes:

> 1. https://github.com/chooglen/git/actions/runs/5294136258
>
> is just
>
> 2. https://github.com/chooglen/git/actions/runs/5292953535
>
> with a fix for "win build", but 2. also failed for completely unrelated
> reasons on osx-*.
>
> Casually clicking through https://github.com/git/git/actions/ suggests
> that others might be experiencing similar failures too?
>
> - https://github.com/git/git/actions/runs/5293250265
> - https://github.com/git/git/actions/runs/5289074140

One of the above two is a topic that mucks with credential seeing a
failure in http test, so I would not be surprised if the topic adds
a test that does not pass on macOS.  Its breakage does seem somewhat
similar to what you are getting.  I didn't check what the above
topic of yours is doing---maybe it is not touching http codepath
and/or the http tests at all?  If that is the case, I would not be
surprised if the existing test is flaky.

The other one is failing tests with p4, which I saw is flaky and
fails to bring up or tear down p4 environment for testing.  I
usually ignore them when I am watching the post-push tests, unless
at a major milestone, in which case I'd "Re-run failed jobs" and
sometimes the breakage goes away (i.e. the failure is flake).

Thanks.

Re: Is MacOS CI flaky?

[Jeff King]

On Fri, Jun 16, 2023 at 03:05:14PM -0700, Glen Choo wrote:

> 1. https://github.com/chooglen/git/actions/runs/5294136258
> 
> is just
> 
> 2. https://github.com/chooglen/git/actions/runs/5292953535
> 
> with a fix for "win build", but 2. also failed for completely unrelated
> reasons on osx-*.

Hrm. So the failure in that first one is in t5559, which made me
immediately suspect http/2 race conditions (because as much as I've
tried to remove them, I still very occasionally see them in my local
builds, and you can definitely trigger them with --stress).

But much to my surprise, the failure is this:

  +++ grep -i 'Authorization: Basic [0-9a-zA-Z+/]' trace
  == Info: h2 [authorization: Basic dXNlckBob3N0OnBhc3NAaG9zdA==]
  == Info: h2 [authorization: Basic dXNlckBob3N0OnBhc3NAaG9zdA==]
  == Info: h2 [authorization: Basic dXNlckBob3N0OnBhc3NAaG9zdA==]
  error: last command exited with $?=1
  not ok 17 - GIT_TRACE_CURL redacts auth details
  #	
  #		rm -rf redact-auth trace &&
  #		set_askpass user@host pass@host &&
  #		GIT_TRACE_CURL="$(pwd)/trace" git clone --bare "$HTTPD_URL/auth/smart/repo.git" redact-auth &&
  #		expect_askpass both user@host &&
  #	
  #		# Ensure that there is no "Basic" followed by a base64 string, but that
  #		# the auth details are redacted
  #		! grep -i "Authorization: Basic [0-9a-zA-Z+/]" trace &&
  #		grep -i "Authorization: Basic <redacted>" trace
  #	

The base64 blob is the actual user/pass we used for auth. That looks
like a real failure. So...for some reason we are racily sometimes not
redacting on macOS? That's super weird, and not something I'd expect to
be racy.

Looking at the string it prints, curl gave us "h2 [...".  But your
b637a41ebe (http: redact curl h2h3 headers in info, 2022-11-11) looks
for "h2h3 [...". I don't know why curl would print one versus the other.
The solution may be something like:

diff --git a/http.c b/http.c
index bb58bb3e6a..283410b3c7 100644
--- a/http.c
+++ b/http.c
@@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)
 	 *   h2h3 [<header-name>: <header-val>]
 	 */
 	if (trace_curl_redact &&
-	    skip_iprefix(header->buf, "h2h3 [", &sensitive_header)) {
+	    skip_iprefix(header->buf, "h2h3 [", &sensitive_header) ||
+	    skip_iprefix(header->buf, "h2 [", &sensitive_header)) {
 		if (redact_sensitive_header(header, sensitive_header - header->buf)) {
 			/* redaction ate our closing bracket */
 			strbuf_addch(header, ']');

but it would be nice to have some explanation of why we would see each
one.

-Peff

[PATCH] http: handle both "h2" and "h2h3" in curl info lines

[Jeff King]

On Sat, Jun 17, 2023 at 12:42:32AM -0400, Jeff King wrote:

> Looking at the string it prints, curl gave us "h2 [...".  But your
> b637a41ebe (http: redact curl h2h3 headers in info, 2022-11-11) looks
> for "h2h3 [...". I don't know why curl would print one versus the other.
> The solution may be something like:
> 
> diff --git a/http.c b/http.c
> index bb58bb3e6a..283410b3c7 100644
> --- a/http.c
> +++ b/http.c
> @@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)
>  	 *   h2h3 [<header-name>: <header-val>]
>  	 */
>  	if (trace_curl_redact &&
> -	    skip_iprefix(header->buf, "h2h3 [", &sensitive_header)) {
> +	    skip_iprefix(header->buf, "h2h3 [", &sensitive_header) ||
> +	    skip_iprefix(header->buf, "h2 [", &sensitive_header)) {
>  		if (redact_sensitive_header(header, sensitive_header - header->buf)) {
>  			/* redaction ate our closing bracket */
>  			strbuf_addch(header, ']');
> 
> but it would be nice to have some explanation of why we would see each
> one.

Ah, I see. It looks like it depends on which version of curl is using.
Perhaps the macOS image in CI has been updated (or maybe the new version
just became available via brew or something). I was able to replicate on
my Linux system by building and linking against curl 8.1.0, and the
patch above (modulo some missing parentheses) fixes it.

So here's that patch with a commit message, though note that t5559.30
seems to reliably fail with a timeout for me on the new version of curl. :(

-- >8 --
Subject: [PATCH] http: handle both "h2" and "h2h3" in curl info lines

When redacting auth tokens in trace output from curl, we look for http/2
headers of the form "h2h3 [header: value]". This comes from b637a41ebe
(http: redact curl h2h3 headers in info, 2022-11-11).

But the "h2h3" prefix changed to just "h2" in curl's fc2f1e547 (http2:
support HTTP/2 to forward proxies, non-tunneling, 2023-04-14). That's in
released version curl 8.1.0; linking against that version means we'll
fail to correctly redact the trace. Our t5559.17 notices and fails.

We can fix this by matching either prefix, which should handle both old
and new versions.

Signed-off-by: Jeff King <peff@peff.net>
---
 http.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/http.c b/http.c
index bb58bb3e6a..b71bb1e3ad 100644
--- a/http.c
+++ b/http.c
@@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)
 	 *   h2h3 [<header-name>: <header-val>]
 	 */
 	if (trace_curl_redact &&
-	    skip_iprefix(header->buf, "h2h3 [", &sensitive_header)) {
+	    (skip_iprefix(header->buf, "h2h3 [", &sensitive_header) ||
+	     skip_iprefix(header->buf, "h2 [", &sensitive_header))) {
 		if (redact_sensitive_header(header, sensitive_header - header->buf)) {
 			/* redaction ate our closing bracket */
 			strbuf_addch(header, ']');
-- 
2.41.0.402.g53108db102

Re: [PATCH] http: handle both "h2" and "h2h3" in curl info lines

[Jeff King]

On Sat, Jun 17, 2023 at 01:15:59AM -0400, Jeff King wrote:

> diff --git a/http.c b/http.c
> index bb58bb3e6a..b71bb1e3ad 100644
> --- a/http.c
> +++ b/http.c
> @@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)
>  	 *   h2h3 [<header-name>: <header-val>]
>  	 */
>  	if (trace_curl_redact &&
> -	    skip_iprefix(header->buf, "h2h3 [", &sensitive_header)) {
> +	    (skip_iprefix(header->buf, "h2h3 [", &sensitive_header) ||
> +	     skip_iprefix(header->buf, "h2 [", &sensitive_header))) {
>  		if (redact_sensitive_header(header, sensitive_header - header->buf)) {
>  			/* redaction ate our closing bracket */
>  			strbuf_addch(header, ']');

I of course found it unsatisfying that we are not taking advantage of
the fact that "h2" is a subset of "h2h3". But optionally skipping past
h3 in the middle of an &&-chain is awkward (you have to write
"skip_prefix() || 1"). We could rewrite it with early returns, as below,
but I think the result is probably less readable.

diff --git a/http.c b/http.c
index b71bb1e3ad..1abfaad4c1 100644
--- a/http.c
+++ b/http.c
@@ -741,17 +741,23 @@ static void redact_sensitive_info_header(struct strbuf *header)
 {
 	const char *sensitive_header;
 
+	if (!trace_curl_redact)
+		return;
+
 	/*
-	 * curl's h2h3 prints headers in info, e.g.:
+	 * curl's http/2 prints headers in info with either an "h2" or an
+	 * "h2h3" prefix, e.g.:
 	 *   h2h3 [<header-name>: <header-val>]
 	 */
-	if (trace_curl_redact &&
-	    (skip_iprefix(header->buf, "h2h3 [", &sensitive_header) ||
-	     skip_iprefix(header->buf, "h2 [", &sensitive_header))) {
-		if (redact_sensitive_header(header, sensitive_header - header->buf)) {
-			/* redaction ate our closing bracket */
-			strbuf_addch(header, ']');
-		}
+	if (!skip_iprefix(header->buf, "h2", &sensitive_header))
+		return;
+	skip_iprefix(sensitive_header, "h3", &sensitive_header);
+	if (!skip_prefix(sensitive_header, " [", &sensitive_header))
+		return;
+
+	if (redact_sensitive_header(header, sensitive_header - header->buf)) {
+		/* redaction ate our closing bracket */
+		strbuf_addch(header, ']');
 	}
 }
 

Re: [PATCH] http: handle both "h2" and "h2h3" in curl info lines

[Jeff King]

On Sat, Jun 17, 2023 at 01:15:59AM -0400, Jeff King wrote:

> So here's that patch with a commit message, though note that t5559.30
> seems to reliably fail with a timeout for me on the new version of curl. :(

OK, looks like the timeout problem is due to another change in curl, but
it has since been fixed. Here are my notes in case anyone else runs into
it (or has to investigate something similar).

My bisection recipe in curl.git is:

  git clean -dx
  autoreconf -fi &&
  ./configure --disable-shared --prefix=/tmp/foo --with-openssl --with-nghttp2 &&
  make install &&
  (cd /path/to/git.git &&
   make CURL_CONFIG=/tmp/foo/bin/curl-config &&
   cd t &&
   ./t5559-http-fetch-smart-http2.sh -v)

You'll need apache with mod_h2 installed so that t5559 can run the
server side of the test.

That bisects to 744dcf22f (http2: flow control and buffer improvements,
2023-03-30), which seems like a plausible candidate. Before that commit,
t5559 runs to completion. After, t5559.30, which tries to send a
large-ish input to the server, hangs for a while and then we eventually
get a 408 timeout error.

Reverse-bisecting from 744dcf22f up to the current tip of "master", it
looks like the problem goes away in 5c58cb021 (http2: fix EOF handling
on uploads with auth negotiation, 2023-05-24), which likewise makes
sense. :)

So I think we can ignore that from the git side, and the patch I posted
earlier is what we'd want to fix the h2/h2h3 confusion.

-Peff

Re: [PATCH] http: handle both "h2" and "h2h3" in curl info lines

[Jeff King]

On Sat, Jun 17, 2023 at 01:15:59AM -0400, Jeff King wrote:

> Ah, I see. It looks like it depends on which version of curl is using.
> Perhaps the macOS image in CI has been updated (or maybe the new version
> just became available via brew or something). I was able to replicate on
> my Linux system by building and linking against curl 8.1.0, and the
> patch above (modulo some missing parentheses) fixes it.

Oh, and just to solve this one remaining riddle: it was indeed a change
in the images. If you click through to the log of the failing osx-clang
job in your first link, then expand "Set up job" and then "Runner
image", you'll see that it was using:

  https://github.com/actions/runner-images/blob/macOS-12/20230612.1/images/macos/macos-12-Readme.md

which mentions curl 8.1.2. Whereas on your other link (where the jobs
did not fail), it was last month's:

  https://github.com/actions/runner-images/blob/macOS-12/20230516.1/images/macos/macos-12-Readme.md

which has curl 8.0.1. So presumably every CI run from here forward will
fail unless we patch it.

-Peff

Re: [PATCH] http: handle both "h2" and "h2h3" in curl info lines

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> On Sat, Jun 17, 2023 at 01:15:59AM -0400, Jeff King wrote:
>
>> Ah, I see. It looks like it depends on which version of curl is using.
>> Perhaps the macOS image in CI has been updated (or maybe the new version
>> just became available via brew or something). I was able to replicate on
>> my Linux system by building and linking against curl 8.1.0, and the
>> patch above (modulo some missing parentheses) fixes it.
>
> Oh, and just to solve this one remaining riddle: it was indeed a change
> in the images. If you click through to the log of the failing osx-clang
> job in your first link, then expand "Set up job" and then "Runner
> image", you'll see that it was using:
>
>   https://github.com/actions/runner-images/blob/macOS-12/20230612.1/images/macos/macos-12-Readme.md
>
> which mentions curl 8.1.2. Whereas on your other link (where the jobs
> did not fail), it was last month's:
>
>   https://github.com/actions/runner-images/blob/macOS-12/20230516.1/images/macos/macos-12-Readme.md
>
> which has curl 8.0.1. So presumably every CI run from here forward will
> fail unless we patch it.

Wow, you are (as usual) thorough.  Thanks for digging.

Re: [PATCH] http: handle both "h2" and "h2h3" in curl info lines

[Glen Choo]

Jeff King <peff@peff.net> writes:

> When redacting auth tokens in trace output from curl, we look for http/2
> headers of the form "h2h3 [header: value]". This comes from b637a41ebe
> (http: redact curl h2h3 headers in info, 2022-11-11).
>
> But the "h2h3" prefix changed to just "h2" in curl's fc2f1e547 (http2:
> support HTTP/2 to forward proxies, non-tunneling, 2023-04-14). That's in
> released version curl 8.1.0; linking against that version means we'll
> fail to correctly redact the trace. Our t5559.17 notices and fails.
>
> We can fix this by matching either prefix, which should handle both old
> and new versions.

Thanks! This patch looks good to me.

I think the approach of matching both patterns literally is better than
trying to catch both `h2h3` and `h2` with a single pattern. Yes, it's
more readable, but it'll also extend better to future changes in curl -
we have no control over what curl might choose to log in the future,
which could be something completely unmatchable.

> Signed-off-by: Jeff King <peff@peff.net>
> ---
>  http.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
>
> diff --git a/http.c b/http.c
> index bb58bb3e6a..b71bb1e3ad 100644
> --- a/http.c
> +++ b/http.c
> @@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)
>  	 *   h2h3 [<header-name>: <header-val>]
>  	 */
>  	if (trace_curl_redact &&
> -	    skip_iprefix(header->buf, "h2h3 [", &sensitive_header)) {
> +	    (skip_iprefix(header->buf, "h2h3 [", &sensitive_header) ||
> +	     skip_iprefix(header->buf, "h2 [", &sensitive_header))) {
>  		if (redact_sensitive_header(header, sensitive_header - header->buf)) {
>  			/* redaction ate our closing bracket */
>  			strbuf_addch(header, ']');
> -- 
> 2.41.0.402.g53108db102