Investigate CI hangs in t3701-add-interactive.sh

[dscho]

In https://github.com/git-for-windows/git-sdk-64/actions/runs/4965633499/jobs/8886995022, the test-minimal-sdk (5) job timed out after six hours. The only test that is not reported as having finished is: t3701-add-interactive.sh.

This most likely has something to do with the 64-bit Git for Windows SDK having been updated from MSYS2 runtime v3.3.6 to v3.4.6. It is quite possible that the "hang" is merely an interactive add waiting for user input, caused by the MSYS2 runtime now defaulting to enable_pcon.

[dscho]

Hmm. While working on some massively-parallel build, I noticed that the output is pretty much garbled at times. I am very, very close to just re-disabling the apparently thoroughly-problematic pseudo console support again, by cherry-picking msys2/msys2-runtime@b74f834

[dscho]

The problem seems to be in t3701.58 "handle very large filtered diff". The git add -p >output 2>&1 <y call seems to hang in the poll() emulation without having read a single byte:

#0  0x00007ff9e448f374 in ntdll!ZwFsControlFile () from C:\WINDOWS\SYSTEM32\ntdll.dll
(gdb) bt
#0  0x00007ff9e448f374 in ntdll!ZwFsControlFile () from C:\WINDOWS\SYSTEM32\ntdll.dll
#1  0x00007ff9e19a87a1 in PeekNamedPipe () from C:\WINDOWS\System32\KernelBase.dll
#2  0x00007ff61b1254e2 in win32_compute_revents (h=0x19c, p_sought=0x4f1ebfdfe8) at compat/poll/poll.c:147
#3  0x00007ff61b125f8c in poll (pfd=0x43fc60506e0, nfd=2, timeout=0) at compat/poll/poll.c:586
#4  0x00007ff61b092ab2 in pump_io_round (slots=0x4f1ebfe9c0, nr=2, pfd=0x43fc60506e0) at run-command.c:1322
#5  0x00007ff61b092d3c in pump_io (slots=0x4f1ebfe9c0, nr=2) at run-command.c:1391
#6  0x00007ff61b093077 in pipe_command (cmd=0x4f1ebfeb10,
    in=0x43fc6480000 "\033[1mdiff --git a/test b/test\033[m\n\033[1mindex 0889435..9812045 100644\033[m\n\033[1m--- a/te
st\033[m\n\033[1m+++ b/test\033[m\n\033[36m@@ -1,6 +1,10000 @@\033[m\n\033[32m+\033[m\033[32m1\033[m\n\033[32m+\033[m\033[32m2\033[m\n\033[32m+\033[m\033[32m3\033[m\n\033[32m+\033[m\033"..., in_len=218949, out=0x4f1ebff020,                     out_hint=218949, err=0x0, err_hint=0) at run-command.c:1455
#7  0x00007ff61af16659 in parse_diff (s=0x4f1ebfed40, ps=0x4f1ebff100) at add-patch.c:469
#8  0x00007ff61af1b163 in run_add_p (r=0x7ff61b27d520 <the_repo>, mode=ADD_P_ADD, revision=0x0, ps=0x4f1ebff100)
    at add-patch.c:1769
#9  0x00007ff61ae14802 in interactive_add (argv=0x43fc60201b0, prefix=0x0, patch=1) at builtin/add.c:169
#10 0x00007ff61ae1500b in cmd_add (argc=1, argv=0x43fc60201a8, prefix=0x0) at builtin/add.c:384
#11 0x00007ff61ae13103 in run_builtin (p=0x7ff61b164020 <commands>, argc=2, argv=0x43fc60201a8) at git.c:469
#12 0x00007ff61ae13570 in handle_builtin (argc=2, argv=0x43fc60201a8) at git.c:724
#13 0x00007ff61ae137a5 in run_argv (argcp=0x4f1ebff610, argv=0x4f1ebff618) at git.c:788
#14 0x00007ff61ae13cd8 in cmd_main (argc=2, argv=0x43fc60201a8) at git.c:923
#15 0x00007ff61af10b7d in main (argc=3, argv=0x43fc60201a0) at common-main.c:62

[dscho]

Sadly, the same hang occurs with MSYS2's build of the MSYS2 runtime v3.4.6.

[dscho]

I am in the middle of bisecting this (fun, fun...) and it seems that something between v3.3.6 and v3.4.0 introduced the bug.

[dscho]

So this bisecting fun is a bit involved. Here are the reasons why:

• Running a full test takes time (in particular due to the POSIX shell time tax imposed on us by Git's test suite). Luckily, I was able to distill a reproducer by reusing the t/trash directory.t3701-add-interactive/ directory and running git reset && git add -N test && git add -p >output 2>&1 <y in it.

• To test a newly-built MSYS2 runtime, it has to be copied over into a working Git for Windows, but no processes can use that MSYS2 runtime when it is copied over. Meaning: not even the Git Bash of that setup. I ended up opening a PowerShell and running this command every time a new MSYS2 runtime was built:

  copy C:\git-sdk-64\usr\src\MSYS2-packages\msys2-runtime\src\wip\x86_64-pc-msys\winsup\cygwin\msys0.dll C:\git-sdk-64-minimal\usr\bin\msys-2.0.dll; if ($?) { C:\git-sdk-64-minimal\usr\bin\bash.exe -lc "uname -a && cd /c/git-sdk-64/usr/src/git/wip/t/trash\ directory.t3701-add-interactive && git reset && git add -N test && git status && { GIT_TRACE=1 GIT_PAGER_IN_USE=true TERM=vt100 ../../git.exe add -p >output 2>&1 <./y; echo $?; git status; }" }

• It is very easy to get the reproducer wrong. I had to restart the git bisect process multiple times merely because my test succeeded for the wrong reason. For example, by mistake I went too far back in the command-line history, forgetting to copy the newly-built MSYS2 runtime 🤦

• When I say "bisect the MSYS2 runtime", it is actually much, much more complex than that. The MSYS2 runtime is maintained as a set of release branches over at https://github.com/msys2/msys2-runtime/. Each of these release branches is based on a Cygwin tag from https://github.com/cygwin/cygwin/. Bisecting through these release branches is pretty pointless because the bug was most likely not introduced by MSYS2's patches (after all, v3.3.6 did not have this bug, but it had these patches). But moving directly to Cygwin's commits does not allow us to build MSYS2 runtimes, but only Cygwin runtimes, with which I cannot run the same test (read: I might find a different bug that only affects Cygwin but not MSYS2 if I bisected the Cygwin runtime versions).

  So I ended up squashing the changes in msys2-3_3_6-release into a single commit on top of cygwin-3_3_6-release and then started bisecting through the Cygwin commit history, in every step re-applying the MSYS2 changes by cherry-picking that commit (and resolving merge conflicts, of which there were many). If this sounds very tedious, then that's because it is.

• The most challenging part of this bisecting session was that Cygwin's source code heavily relies on an autoconf-based build, and unfortunately Cygwin's definitions are not quite correct, rendering many incremental builds incorrect. I only figured this out by stumbling multiple times into a commit that was labeled both good and bad by git bisect.

  This means that I had to restart the bisection for the 11,593th time, but now, with every bisection step, I had to throw away all previously-generated files, configure, Makefile.in, compiled object files, extending every bisection step to take roughly 15 minutes. This is taxing my focus, to say it kindly.

I am finally at a point where I left git bisect behind because I got so confused so often and there was no way to leave notes with the individual builds. That also allows me to pick the candidate commits a bit more smartly, based on the commit messages. I'm now down to the following candidates:

• cygwin/cygwin@8d8724ee1b Cygwin: pty: Fix Ctrl-C handling further for non-cygwin apps. (hangs!)
• cygwin/cygwin@90788821b7 Cygwin: pipe: Restore blocking mode for cygwin process at startup.
• cygwin/cygwin@451bbfb9f3 Cygwin: Document that the pipe_byte option is now set by default
• cygwin/cygwin@d9c1aeaddf Cygwin: fhandler_pipe::raw_read: minor code cleanup
• cygwin/cygwin@9e4d308cd5 Cygwin: pipe: Adopt FILE_SYNCHRONOUS_IO_NONALERT flag for read pipe.
• cygwin/cygwin@f3d719c694 Cygwin: console: Fix console mode of non-cygwin apps in background. (does not hang!)

Based on past experience, I strongly suspect cygwin/cygwin@90788821b7 (with the same authorship as so many pseudo console commits that I battled in the past).

[dscho]

I strongly suspect cygwin/cygwin@90788821b7

Indeed it is. Reverting it on top of Git for Windows' current MSYS2 runtime "fixes" the issue.

Now, what does this re-break if we revert that commit? Let's dig some. Apparently there was some conversation around merging a branch with the buggy commit as its tip commit: https://inbox.sourceware.org/cygwin-developers/20211212222631.faffbddc15eb3b3a2cfa2768@nifty.ne.jp/. This was the culmination, apparently, of a thread that started on a different mailing list: https://inbox.sourceware.org/cygwin/CAEv6GOB8PXHgHoz7hdJy6Bia2GWEmUDnTd252gTGinz2vuv=hA@mail.gmail.com/. And that bug report was in response to none other than me myself identifying this as a bug in Cygwin: git-ecosystem/git-credential-manager#509 (comment). But that bug was in the scenario where a C# program (Git Credential Manager) talked to a Cygwin git.exe.

Plus, the suggested work-around to use CYGWIN=pipe_byte (or, in our case, MSYS=pipe_byte) does not seem to fix this here issue.

So, under the assumption that we do not really need to bother with supporting GCM to talk to an MSYS git.exe in Git for Windows, I will unceremoniously revert that commit in Git for Windows' fork of the MSYS2 runtime.

And who knows? Maybe this could be the workaround we need to fix the mysterious hangs on Windows/ARM64?