Is MacOS CI flaky?

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

Glen Choo <chooglen@google.com> writes:

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.

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

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:

On Sat, Jun 17, 2023 at 12:42:32AM -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.

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(-)

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

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.

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

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

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

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

Jeff King <peff@peff.net> writes:

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

Jeff King <peff@peff.net> writes:

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.