{"thread":{"id":"59877","subject":"Is MacOS CI flaky?","startedAt":"2023-06-16T22:05:27Z","lastAt":"2023-06-20T20:32:10Z","messageCount":9,"participants":["Glen Choo","Junio C Hamano","Jeff King"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"478477","messageId":"kl6lilbnrrl1.fsf@chooglen-macbookpro.roam.corp.google.com","threadId":"59877","inReplyTo":null,"subject":"Is MacOS CI flaky?","fromName":"Glen Choo","fromEmail":"chooglen@google.com","sentAt":"2023-06-16T22:05:14Z","receivedAt":"2023-06-16T22:05:27Z","isPatch":false,"sender":{"key":"glencbz@gmail.com","avatar":"https://avatars.githubusercontent.com/u/58092771?v=4"},"body":"\n1. https://github.com/chooglen/git/actions/runs/5294136258\n\nis just\n\n2. https://github.com/chooglen/git/actions/runs/5292953535\n\nwith a fix for \"win build\", but 2. also failed for completely unrelated\nreasons on osx-*.\n\nCasually clicking through https://github.com/git/git/actions/ suggests\nthat others might be experiencing similar failures too?\n\n- https://github.com/git/git/actions/runs/5293250265\n- https://github.com/git/git/actions/runs/5289074140\n"},{"id":"478493","messageId":"xmqqjzw3rn07.fsf@gitster.g","threadId":"59877","inReplyTo":"kl6lilbnrrl1.fsf@chooglen-macbookpro.roam.corp.google.com","subject":"Re: Is MacOS CI flaky?","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2023-06-16T23:44:08Z","receivedAt":"2023-06-16T23:44:13Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Glen Choo writes:\n\n> 1. https://github.com/chooglen/git/actions/runs/5294136258\n>\n> is just\n>\n> 2. https://github.com/chooglen/git/actions/runs/5292953535\n>\n> with a fix for \"win build\", but 2. also failed for completely unrelated\n> reasons on osx-*.\n>\n> Casually clicking through https://github.com/git/git/actions/ suggests\n> that others might be experiencing similar failures too?\n>\n> - https://github.com/git/git/actions/runs/5293250265\n> - https://github.com/git/git/actions/runs/5289074140\n\nOne of the above two is a topic that mucks with credential seeing a\nfailure in http test, so I would not be surprised if the topic adds\na test that does not pass on macOS. Its breakage does seem somewhat\nsimilar to what you are getting. I didn't check what the above\ntopic of yours is doing---maybe it is not touching http codepath\nand/or the http tests at all? If that is the case, I would not be\nsurprised if the existing test is flaky.\n\nThe other one is failing tests with p4, which I saw is flaky and\nfails to bring up or tear down p4 environment for testing. I\nusually ignore them when I am watching the post-push tests, unless\nat a major milestone, in which case I'd \"Re-run failed jobs\" and\nsometimes the breakage goes away (i.e. the failure is flake).\n\nThanks.\n"},{"id":"478498","messageId":"20230617044232.GC562686@coredump.intra.peff.net","threadId":"59877","inReplyTo":"kl6lilbnrrl1.fsf@chooglen-macbookpro.roam.corp.google.com","subject":"Re: Is MacOS CI flaky?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2023-06-17T04:42:32Z","receivedAt":"2023-06-17T04:42:39Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Jun 16, 2023 at 03:05:14PM -0700, Glen Choo wrote:\n\n> 1. https://github.com/chooglen/git/actions/runs/5294136258\n> \n> is just\n> \n> 2. https://github.com/chooglen/git/actions/runs/5292953535\n> \n> with a fix for \"win build\", but 2. also failed for completely unrelated\n> reasons on osx-*.\n\nHrm. So the failure in that first one is in t5559, which made me\nimmediately suspect http/2 race conditions (because as much as I've\ntried to remove them, I still very occasionally see them in my local\nbuilds, and you can definitely trigger them with --stress).\n\nBut much to my surprise, the failure is this:\n\n +++ grep -i 'Authorization: Basic [0-9a-zA-Z+/]' trace\n == Info: h2 [authorization: Basic dXNlckBob3N0OnBhc3NAaG9zdA==]\n == Info: h2 [authorization: Basic dXNlckBob3N0OnBhc3NAaG9zdA==]\n == Info: h2 [authorization: Basic dXNlckBob3N0OnBhc3NAaG9zdA==]\n error: last command exited with $?=1\n not ok 17 - GIT_TRACE_CURL redacts auth details\n #\t\n #\t\trm -rf redact-auth trace &&\n #\t\tset_askpass user@host pass@host &&\n #\t\tGIT_TRACE_CURL=\"$(pwd)/trace\" git clone --bare \"$HTTPD_URL/auth/smart/repo.git\" redact-auth &&\n #\t\texpect_askpass both user@host &&\n #\t\n #\t\t# Ensure that there is no \"Basic\" followed by a base64 string, but that\n #\t\t# the auth details are redacted\n #\t\t! grep -i \"Authorization: Basic [0-9a-zA-Z+/]\" trace &&\n #\t\tgrep -i \"Authorization: Basic \" trace\n #\t\n\nThe base64 blob is the actual user/pass we used for auth. That looks\nlike a real failure. So...for some reason we are racily sometimes not\nredacting on macOS? That's super weird, and not something I'd expect to\nbe racy.\n\nLooking at the string it prints, curl gave us \"h2 [...\". But your\nb637a41ebe (http: redact curl h2h3 headers in info, 2022-11-11) looks\nfor \"h2h3 [...\". I don't know why curl would print one versus the other.\nThe solution may be something like:\n\ndiff --git a/http.c b/http.c\nindex bb58bb3e6a..283410b3c7 100644\n--- a/http.c\n+++ b/http.c\n@@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)\n \t * h2h3 [: ]\n \t */\n \tif (trace_curl_redact &&\n-\t skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header)) {\n+\t skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header) ||\n+\t skip_iprefix(header->buf, \"h2 [\", &sensitive_header)) {\n \t\tif (redact_sensitive_header(header, sensitive_header - header->buf)) {\n \t\t\t/* redaction ate our closing bracket */\n \t\t\tstrbuf_addch(header, ']');\n\nbut it would be nice to have some explanation of why we would see each\none.\n\n-Peff\n"},{"id":"478499","messageId":"20230617051559.GD562686@coredump.intra.peff.net","threadId":"59877","inReplyTo":"20230617044232.GC562686@coredump.intra.peff.net","subject":"[PATCH] http: handle both \"h2\" and \"h2h3\" in curl info lines","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2023-06-17T05:15:59Z","receivedAt":"2023-06-17T05:16:06Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sat, Jun 17, 2023 at 12:42:32AM -0400, Jeff King wrote:\n\n> Looking at the string it prints, curl gave us \"h2 [...\". But your\n> b637a41ebe (http: redact curl h2h3 headers in info, 2022-11-11) looks\n> for \"h2h3 [...\". I don't know why curl would print one versus the other.\n> The solution may be something like:\n> \n> diff --git a/http.c b/http.c\n> index bb58bb3e6a..283410b3c7 100644\n> --- a/http.c\n> +++ b/http.c\n> @@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)\n> \t * h2h3 [: ]\n> \t */\n> \tif (trace_curl_redact &&\n> -\t skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header)) {\n> +\t skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header) ||\n> +\t skip_iprefix(header->buf, \"h2 [\", &sensitive_header)) {\n> \t\tif (redact_sensitive_header(header, sensitive_header - header->buf)) {\n> \t\t\t/* redaction ate our closing bracket */\n> \t\t\tstrbuf_addch(header, ']');\n> \n> but it would be nice to have some explanation of why we would see each\n> one.\n\nAh, I see. It looks like it depends on which version of curl is using.\nPerhaps the macOS image in CI has been updated (or maybe the new version\njust became available via brew or something). I was able to replicate on\nmy Linux system by building and linking against curl 8.1.0, and the\npatch above (modulo some missing parentheses) fixes it.\n\nSo here's that patch with a commit message, though note that t5559.30\nseems to reliably fail with a timeout for me on the new version of curl. :(\n\n-- >8 --\nSubject: [PATCH] http: handle both \"h2\" and \"h2h3\" in curl info lines\n\nWhen redacting auth tokens in trace output from curl, we look for http/2\nheaders of the form \"h2h3 [header: value]\". This comes from b637a41ebe\n(http: redact curl h2h3 headers in info, 2022-11-11).\n\nBut the \"h2h3\" prefix changed to just \"h2\" in curl's fc2f1e547 (http2:\nsupport HTTP/2 to forward proxies, non-tunneling, 2023-04-14). That's in\nreleased version curl 8.1.0; linking against that version means we'll\nfail to correctly redact the trace. Our t5559.17 notices and fails.\n\nWe can fix this by matching either prefix, which should handle both old\nand new versions.\n\nSigned-off-by: Jeff King \n---\n http.c | 3 ++-\n 1 file changed, 2 insertions(+), 1 deletion(-)\n\ndiff --git a/http.c b/http.c\nindex bb58bb3e6a..b71bb1e3ad 100644\n--- a/http.c\n+++ b/http.c\n@@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)\n \t * h2h3 [: ]\n \t */\n \tif (trace_curl_redact &&\n-\t skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header)) {\n+\t (skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header) ||\n+\t skip_iprefix(header->buf, \"h2 [\", &sensitive_header))) {\n \t\tif (redact_sensitive_header(header, sensitive_header - header->buf)) {\n \t\t\t/* redaction ate our closing bracket */\n \t\t\tstrbuf_addch(header, ']');\n-- \n2.41.0.402.g53108db102\n\n"},{"id":"478500","messageId":"20230617053129.GE562686@coredump.intra.peff.net","threadId":"59877","inReplyTo":"20230617051559.GD562686@coredump.intra.peff.net","subject":"Re: [PATCH] http: handle both \"h2\" and \"h2h3\" in curl info lines","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2023-06-17T05:31:29Z","receivedAt":"2023-06-17T05:31:38Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sat, Jun 17, 2023 at 01:15:59AM -0400, Jeff King wrote:\n\n> diff --git a/http.c b/http.c\n> index bb58bb3e6a..b71bb1e3ad 100644\n> --- a/http.c\n> +++ b/http.c\n> @@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)\n> \t * h2h3 [: ]\n> \t */\n> \tif (trace_curl_redact &&\n> -\t skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header)) {\n> +\t (skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header) ||\n> +\t skip_iprefix(header->buf, \"h2 [\", &sensitive_header))) {\n> \t\tif (redact_sensitive_header(header, sensitive_header - header->buf)) {\n> \t\t\t/* redaction ate our closing bracket */\n> \t\t\tstrbuf_addch(header, ']');\n\nI of course found it unsatisfying that we are not taking advantage of\nthe fact that \"h2\" is a subset of \"h2h3\". But optionally skipping past\nh3 in the middle of an &&-chain is awkward (you have to write\n\"skip_prefix() || 1\"). We could rewrite it with early returns, as below,\nbut I think the result is probably less readable.\n\ndiff --git a/http.c b/http.c\nindex b71bb1e3ad..1abfaad4c1 100644\n--- a/http.c\n+++ b/http.c\n@@ -741,17 +741,23 @@ static void redact_sensitive_info_header(struct strbuf *header)\n {\n \tconst char *sensitive_header;\n \n+\tif (!trace_curl_redact)\n+\t\treturn;\n+\n \t/*\n-\t * curl's h2h3 prints headers in info, e.g.:\n+\t * curl's http/2 prints headers in info with either an \"h2\" or an\n+\t * \"h2h3\" prefix, e.g.:\n \t * h2h3 [: ]\n \t */\n-\tif (trace_curl_redact &&\n-\t (skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header) ||\n-\t skip_iprefix(header->buf, \"h2 [\", &sensitive_header))) {\n-\t\tif (redact_sensitive_header(header, sensitive_header - header->buf)) {\n-\t\t\t/* redaction ate our closing bracket */\n-\t\t\tstrbuf_addch(header, ']');\n-\t\t}\n+\tif (!skip_iprefix(header->buf, \"h2\", &sensitive_header))\n+\t\treturn;\n+\tskip_iprefix(sensitive_header, \"h3\", &sensitive_header);\n+\tif (!skip_prefix(sensitive_header, \" [\", &sensitive_header))\n+\t\treturn;\n+\n+\tif (redact_sensitive_header(header, sensitive_header - header->buf)) {\n+\t\t/* redaction ate our closing bracket */\n+\t\tstrbuf_addch(header, ']');\n \t}\n }\n \n"},{"id":"478501","messageId":"20230617054519.GF562686@coredump.intra.peff.net","threadId":"59877","inReplyTo":"20230617051559.GD562686@coredump.intra.peff.net","subject":"Re: [PATCH] http: handle both \"h2\" and \"h2h3\" in curl info lines","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2023-06-17T05:45:19Z","receivedAt":"2023-06-17T05:45:27Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sat, Jun 17, 2023 at 01:15:59AM -0400, Jeff King wrote:\n\n> So here's that patch with a commit message, though note that t5559.30\n> seems to reliably fail with a timeout for me on the new version of curl. :(\n\nOK, looks like the timeout problem is due to another change in curl, but\nit has since been fixed. Here are my notes in case anyone else runs into\nit (or has to investigate something similar).\n\nMy bisection recipe in curl.git is:\n\n git clean -dx\n autoreconf -fi &&\n ./configure --disable-shared --prefix=/tmp/foo --with-openssl --with-nghttp2 &&\n make install &&\n (cd /path/to/git.git &&\n make CURL_CONFIG=/tmp/foo/bin/curl-config &&\n cd t &&\n ./t5559-http-fetch-smart-http2.sh -v)\n\nYou'll need apache with mod_h2 installed so that t5559 can run the\nserver side of the test.\n\nThat bisects to 744dcf22f (http2: flow control and buffer improvements,\n2023-03-30), which seems like a plausible candidate. Before that commit,\nt5559 runs to completion. After, t5559.30, which tries to send a\nlarge-ish input to the server, hangs for a while and then we eventually\nget a 408 timeout error.\n\nReverse-bisecting from 744dcf22f up to the current tip of \"master\", it\nlooks like the problem goes away in 5c58cb021 (http2: fix EOF handling\non uploads with auth negotiation, 2023-05-24), which likewise makes\nsense. :)\n\nSo I think we can ignore that from the git side, and the patch I posted\nearlier is what we'd want to fix the h2/h2h3 confusion.\n\n-Peff\n"},{"id":"478510","messageId":"20230617080705.GA2151825@coredump.intra.peff.net","threadId":"59877","inReplyTo":"20230617051559.GD562686@coredump.intra.peff.net","subject":"Re: [PATCH] http: handle both \"h2\" and \"h2h3\" in curl info lines","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2023-06-17T08:07:05Z","receivedAt":"2023-06-17T08:07:15Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sat, Jun 17, 2023 at 01:15:59AM -0400, Jeff King wrote:\n\n> Ah, I see. It looks like it depends on which version of curl is using.\n> Perhaps the macOS image in CI has been updated (or maybe the new version\n> just became available via brew or something). I was able to replicate on\n> my Linux system by building and linking against curl 8.1.0, and the\n> patch above (modulo some missing parentheses) fixes it.\n\nOh, and just to solve this one remaining riddle: it was indeed a change\nin the images. If you click through to the log of the failing osx-clang\njob in your first link, then expand \"Set up job\" and then \"Runner\nimage\", you'll see that it was using:\n\n https://github.com/actions/runner-images/blob/macOS-12/20230612.1/images/macos/macos-12-Readme.md\n\nwhich mentions curl 8.1.2. Whereas on your other link (where the jobs\ndid not fail), it was last month's:\n\n https://github.com/actions/runner-images/blob/macOS-12/20230516.1/images/macos/macos-12-Readme.md\n\nwhich has curl 8.0.1. So presumably every CI run from here forward will\nfail unless we patch it.\n\n-Peff\n"},{"id":"478512","messageId":"xmqq352qsb8g.fsf@gitster.g","threadId":"59877","inReplyTo":"20230617080705.GA2151825@coredump.intra.peff.net","subject":"Re: [PATCH] http: handle both \"h2\" and \"h2h3\" in curl info lines","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2023-06-17T09:13:03Z","receivedAt":"2023-06-17T09:13:15Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> On Sat, Jun 17, 2023 at 01:15:59AM -0400, Jeff King wrote:\n>\n>> Ah, I see. It looks like it depends on which version of curl is using.\n>> Perhaps the macOS image in CI has been updated (or maybe the new version\n>> just became available via brew or something). I was able to replicate on\n>> my Linux system by building and linking against curl 8.1.0, and the\n>> patch above (modulo some missing parentheses) fixes it.\n>\n> Oh, and just to solve this one remaining riddle: it was indeed a change\n> in the images. If you click through to the log of the failing osx-clang\n> job in your first link, then expand \"Set up job\" and then \"Runner\n> image\", you'll see that it was using:\n>\n> https://github.com/actions/runner-images/blob/macOS-12/20230612.1/images/macos/macos-12-Readme.md\n>\n> which mentions curl 8.1.2. Whereas on your other link (where the jobs\n> did not fail), it was last month's:\n>\n> https://github.com/actions/runner-images/blob/macOS-12/20230516.1/images/macos/macos-12-Readme.md\n>\n> which has curl 8.0.1. So presumably every CI run from here forward will\n> fail unless we patch it.\n\nWow, you are (as usual) thorough. Thanks for digging.\n"},{"id":"478592","messageId":"kl6l8rcdswn6.fsf@chooglen-macbookpro.roam.corp.google.com","threadId":"59877","inReplyTo":"20230617051559.GD562686@coredump.intra.peff.net","subject":"Re: [PATCH] http: handle both \"h2\" and \"h2h3\" in curl info lines","fromName":"Glen Choo","fromEmail":"chooglen@google.com","sentAt":"2023-06-20T20:31:57Z","receivedAt":"2023-06-20T20:32:10Z","isPatch":true,"sender":{"key":"glencbz@gmail.com","avatar":"https://avatars.githubusercontent.com/u/58092771?v=4"},"body":"Jeff King writes:\n\n> When redacting auth tokens in trace output from curl, we look for http/2\n> headers of the form \"h2h3 [header: value]\". This comes from b637a41ebe\n> (http: redact curl h2h3 headers in info, 2022-11-11).\n>\n> But the \"h2h3\" prefix changed to just \"h2\" in curl's fc2f1e547 (http2:\n> support HTTP/2 to forward proxies, non-tunneling, 2023-04-14). That's in\n> released version curl 8.1.0; linking against that version means we'll\n> fail to correctly redact the trace. Our t5559.17 notices and fails.\n>\n> We can fix this by matching either prefix, which should handle both old\n> and new versions.\n\nThanks! This patch looks good to me.\n\nI think the approach of matching both patterns literally is better than\ntrying to catch both `h2h3` and `h2` with a single pattern. Yes, it's\nmore readable, but it'll also extend better to future changes in curl -\nwe have no control over what curl might choose to log in the future,\nwhich could be something completely unmatchable.\n\n> Signed-off-by: Jeff King \n> ---\n> http.c | 3 ++-\n> 1 file changed, 2 insertions(+), 1 deletion(-)\n>\n> diff --git a/http.c b/http.c\n> index bb58bb3e6a..b71bb1e3ad 100644\n> --- a/http.c\n> +++ b/http.c\n> @@ -746,7 +746,8 @@ static void redact_sensitive_info_header(struct strbuf *header)\n> \t * h2h3 [: ]\n> \t */\n> \tif (trace_curl_redact &&\n> -\t skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header)) {\n> +\t (skip_iprefix(header->buf, \"h2h3 [\", &sensitive_header) ||\n> +\t skip_iprefix(header->buf, \"h2 [\", &sensitive_header))) {\n> \t\tif (redact_sensitive_header(header, sensitive_header - header->buf)) {\n> \t\t\t/* redaction ate our closing bracket */\n> \t\t\tstrbuf_addch(header, ']');\n> -- \n> 2.41.0.402.g53108db102\n\n"}]}