Hanging on domain joined systems

[seppestas]

• I was not able to find an open or closed issue matching what I'm seeing

Setup

• Which version of Git for Windows are you using? Is it 32-bit or 64-bit?

$ git --version --build-options

git version 2.43.0.windows.1
cpu: x86_64
built from commit: 4b968f3ea3b32a7bc50846bab49f3f381841d297
sizeof-long: 4
sizeof-size_t: 8
shell-path: /bin/sh
feature: fsmonitor--daemon

• Which version of Windows are you running? Vista, 7, 8, 10? Is it 32-bit or 64-bit?

$ cmd.exe /c ver

Microsoft Windows [Version 10.0.22621.3085]

• What options did you set as part of the installation? Or did you choose the
  defaults?

# One of the following:
> type "C:\Program Files\Git\etc\install-options.txt"

Editor Option: VIM
Custom Editor Path:
Default Branch Option:
Path Option: Cmd
SSH Option: OpenSSH
Tortoise Option: false
CURL Option: OpenSSL
CRLF Option: CRLFAlways
Bash Terminal Option: MinTTY
Git Pull Behavior Option: Merge
Use Credential Manager: Enabled
Performance Tweaks FSCache: Enabled
Enable Symlinks: Disabled
Enable Pseudo Console Support: Disabled
Enable FSMonitor: Disabled

Git was installed with chocolatey.

• Any other interesting things about your environment that might be related
  to the issue you're seeing?

Domain joined system in a WFH scenario, i.e. set up to use a domain controller, but the domain controller is only reachable over VPN.

Details

• Which terminal/shell are you running Git from? e.g Bash/CMD/PowerShell/other

Primarily Powershell, but the same problem exists when using CMD. Bash (Git Bash) has a large start-up time.

• What commands did you run to trigger this issue? If you can provide a
  Minimal, Complete, and Verifiable example
  this will help us understand the issue.

git log
echo "Hello, world" | less

• What did you expect to occur after running these commands?

This commands should be quick, especially on a small repo.

• What actually happened instead?

The commands hang for a long time. E.g

C:\Program Files\Git\usr\bin> echo "Hello, world" | ./less
C:\Program Files\Git\usr\bin> get-history | fl
...
Id                 : 20
CommandLine        : echo "Hello, world" | ./less
ExecutionStatus    : Completed
StartExecutionTime : 19/01/2024 17:20:05
EndExecutionTime   : 19/01/2024 17:20:22

The issues seems to be resolved when connecting to the corporate VPN network, i.e. when the domain controller is reachable, suggesting an issue similar to #4459. I was also able to see many git / Cygwin commands performing attempts to talk to the domain controller. My guess is that these attempt have to time out before the commands can complete.

[dscho]

C:\Program Files\Git\usr\bin> echo "Hello, world" | ./less

Could you echo "Hello, world" | ./strace -o "$env:USERPROFILE/hello.trace" ./less and look at the last lines of that hello.trace while it is waiting, to see whether anything obvious strikes you as the culprit?

[seppestas]

I did another test and installed Git for Windows from the installer. I no longer seem to notice any big hangs, though the delays were somewhat intermittent before. It could be the problem only occurs when installing from Chocolaty (or just re-installing somehow fixed it).

> git --version --build-options
git version 2.43.0.windows.1
cpu: x86_64
built from commit: 4b968f3ea3b32a7bc50846bab49f3f381841d297
sizeof-long: 4
sizeof-size_t: 8
shell-path: /bin/sh
feature: fsmonitor--daemon

> type "C:\Program Files\Git\etc\install-options.txt"

Editor Option: VisualStudioCode
Custom Editor Path:
Default Branch Option:
Path Option: Cmd
SSH Option: OpenSSH
Tortoise Option: false
CURL Option: OpenSSL
CRLF Option: CRLFAlways
Bash Terminal Option: MinTTY
Git Pull Behavior Option: Merge
Use Credential Manager: Enabled
Performance Tweaks FSCache: Enabled
Enable Symlinks: Disabled
Enable Pseudo Console Support: Disabled
Enable FSMonitor: Disabled

Still, looking into the suggested strace output (with the new, non-hanging or at least seemingly faster, Git installation):

...
  117    9677 [main] less (20792) dll_list::forkable_ntnamesize: disabled, missing or not on NTFS \??\C:\Program Files\Git\var\run\cygfork
--- Process 20792 loaded C:\Windows\System32\umppc17807.dll at 0000000000630000
--- Process 20792 unloaded DLL at 0000000000630000
--- Process 20792 loaded C:\Windows\System32\umppc17807.dll at 0000000000630000
--- Process 17312 loaded C:\Program Files\Avecto\Privilege Guard Client\PGHook.dll at 0000...c3470000
--- Process 17312, exception c0000005 at 000000000079...
--- Process 17312, exception c0000005 at 000000021006...
--- Process 17312, exception c0000005 at 000000021006...
(repeated a total of 533 times)
--- Process 20792 thread 8172 exited with status 0xc0000...
--- Process 20792 thread 4140 exited with status 0xc0000...
--- Process 20792 thread 16080 exited with status 0xc000...
--- Process 20792 exited with status 0xc0000005

(Not connected to VPN, results look similar when connected. I redacted parts of some of the addresses just to be sure, I don't think it's sensitive, but I'd rather be safe than sorry).

So maybe Privilege Guard is the thing doing the domain lookups, I'll check with IT.

[seppestas]

(un)fortunately, re-installing git using chocolaty again did not bring the issue back, and the output of strace looks the same.

I'll try to get a strace log again when I notice delays.

[seppestas]

Interestingly, when I run a git command with strace it is faster than without.

> get-history | fl
Id                 : 25
CommandLine        : & 'C:\Program Files\Git\usr\bin\strace.exe' git log
ExecutionStatus    : Completed
StartExecutionTime : 21/02/2024 18:02:53
EndExecutionTime   : 21/02/2024 18:02:54

Id                 : 26
CommandLine        : git log
ExecutionStatus    : Completed
StartExecutionTime : 21/02/2024 18:06:31
EndExecutionTime   : 21/02/2024 18:07:10

The strace output shows that most of the time is spent on the same "Process 23180, exception c0000005 at ..." .

In some cases, seemingly when running git log for the first time in a while on a repo, it can take multiple minutes to complete, absolutely breaking my workflow (same relatively small repo checked out in a different location):

Id                 : 60
CommandLine        : git log
ExecutionStatus    : Completed
StartExecutionTime : 21/02/2024 18:16:29
EndExecutionTime   : 21/02/2024 18:19:04

[seppestas]

I was also able to figure out:

• git commands are fast when run a second time but slow down again if the index changes
• git log is hanging on less, but attaching strace is not possible:

strace -p (Get-Process less).id
strace.exe: couldn't attach to pid 29076 for debugging

[dscho]

So maybe Privilege Guard is the thing doing the domain lookups,

Could be. And those Access Violations (0xC0000005) certainly look concerning.

[seppestas]

Frustratingly, I can't seem to reproduce less hanging, but I can easily reproduce git log hanging for ~ 20 seconds, both with git installed from the chocolaty website and by running the installer from the website.

Is there any way to run git log in strace? Whenever I try I get the following error:

strace.exe: error creating process C:\Program Files\Git\mingw64\bin\git.exe, (error 50)

[dscho]

Is there any way to run git log in strace? Whenever I try I get the following error:

strace.exe: error creating process C:\Program Files\Git\mingw64\bin\git.exe, (error 50)

That's because strace only works on MSYS/Cygwin programs, and git.exe isn't (it's a MINGW program). However, less.exe is, and you should be able to tell Git to run it through strace by something like:

GIT_PAGER="strace -o /tmp/a1 less.exe" git log -20

[seppestas]

Thanks @dscho, I was able to find out a bit more thanks to this

It looks like quite a bit of time is spent opening "cygpid.59"

1222797 1473407 [main] less 89 open_shared: name cygpid.59, shared 0x1A4030000 (wanted 0x1A4030000), h 0x22C, m 6, created 0

I'm still trying to figure out what exactly this means.

On thing that might cause issues is that I have multiple cygwin and MinGW Unix tools installed on my system (Git for Windows, TDM-GCC-64 and an old Cygwin 3.4 I need for a legacy toolchain). It looks like git log uses at least some parts of Cygwin 3.4, which makes sense because it's on my PATH. e.g:

57   51727 [main] less 89 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin340\bin, 0x10000100, no-add-slash)

However, even when removing the Cygwin 3.4 Unix commands from my PATH, git log is still slow. No notable improvement was observed (though I assume it's still better to use the Cygwin commands included with git for Windows).

Interestingly, even if I connect to the VPN, resulting in a fast git log, the cygpid.59 thing still shows up in strace:

1156236 1363285 [main] less 97 open_shared: name cygpid.59, shared 0x1A4030000 (wanted 0x1A4030000), h 0x234, m 6, created 0

It could however explain why I was seeing improvements after re-installing git.

1156236 is only ~ 1 second. git log takes about 20 seconds when not connected to VPN, ~2 seconds when connected to VPN.

Is there any other internal process git might be using that could slow down as a result of the domain server being unavailable?

[seppestas]

TL;DR: in Powershell, setting the HOME environmental variable seems to resolve the issue (even though the HOME env var is already set for my user in Windows).

By looking at the Windows event viewer, something seems to be blocking my git commands before they make it to the pager.

From a git diff command on a file with only one line changed:

2024-03-19T17:03:00.9578113Z 
Process Information:
	New Process ID:		0x2928
	New Process Name:	C:\Program Files\Git\cmd\git.exe
	Token Elevation Type:	TokenElevationTypeDefault (1)
	Mandatory Label:		Mandatory Label\Medium Mandatory Level
	Creator Process ID:	0x652c
	Creator Process Name:	C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe
	Process Command Line:
2024-03-19T17:03:01.0303160Z
Process Information:
	New Process ID:		0x6564
	New Process Name:	C:\Program Files\Git\mingw64\bin\git.exe
	Token Elevation Type:	TokenElevationTypeDefault (1)
	Mandatory Label:		Mandatory Label\Medium Mandatory Level
	Creator Process ID:	0x2928
	Creator Process Name:	C:\Program Files\Git\cmd\git.exe
	Process Command Line:	
2024-03-19T17:03:01.1214764Z
Process Information:
	New Process ID:		0x4850
	New Process Name:	C:\Program Files\Git\usr\bin\sh.exe
	Token Elevation Type:	TokenElevationTypeDefault (1)
	Mandatory Label:		Mandatory Label\Medium Mandatory Level
	Creator Process ID:	0x6564
	Creator Process Name:	C:\Program Files\Git\mingw64\bin\git.exe
	Process Command Line:	
2024-03-19T17:03:16.2597315Z
Process Information:
	New Process ID:		0x7d8c
	New Process Name:	C:\Program Files\Git\usr\bin\strace.exe
	Token Elevation Type:	TokenElevationTypeDefault (1)
	Mandatory Label:		Mandatory Label\Medium Mandatory Level
	Creator Process ID:	0x4850
	Creator Process Name:	C:\Program Files\Git\usr\bin\sh.exe
	Process Command Line:	
2024-03-19T17:03:16.3252408Z 
Process Information:
	New Process ID:		0x94f8
	New Process Name:	C:\Program Files\Git\usr\bin\less.exe
	Token Elevation Type:	TokenElevationTypeDefault (1)
	Mandatory Label:		Mandatory Label\Medium Mandatory Level
	Creator Process ID:	0x7d8c
	Creator Process Name:	C:\Program Files\Git\usr\bin\strace.exe
	Process Command Line:

Looking at git trace of the same command, it looks like the delay occurs somewhere between strace and sh:

17:21:03.443297 exec-cmd.c:244          trace: resolved executable dir: C:/Program Files/Git/mingw64/bin
17:21:03.453171 git.c:463               trace: built-in: git diff ncu/.settings/com.digi.netos.prefs
17:21:03.457171 run-command.c:659       trace: run_command: unset GIT_PAGER_IN_USE; LESS=FRX LV=-c 'strace -o /c/Users/sstas/strace-logs/less-pager-glog-no-

> get-history | fl
...
Id                 : 48
CommandLine        : git diff ncu/.settings/com.digi.netos.prefs
ExecutionStatus    : Completed
StartExecutionTime : 19/03/2024 17:03:00
EndExecutionTime   : 19/03/2024 17:03:16
Id                 : 51
...
CommandLine        : git diff ncu/.settings/com.digi.netos.prefs
ExecutionStatus    : Completed
StartExecutionTime : 19/03/2024 17:21:03
EndExecutionTime   : 19/03/2024 17:21:18

Looking into the trace logs, less itself takes < 1second, but I did notice

  116   36473 [main] less 2065 getwinenv: can't set native for HOME= since no environ yet

This is unexpected, because the HOME env var is set as user variable in windows as a Windows path (HOME=C:\Users\sstas). Running the same command with HOME set from Powershell seems to resolve the issue (but doesn't remove the variable from the trace?!).

In git shell (bash), export HOME=/c/Users/sstas/ nor export HOME=C:\\Users\\sstas\\ seems to work (both still result in slow

My guess is some Cygwin tool is trying to find my home folder, it's for some reason not picking up the HOME env var and on my domain joined system it results in it trying to ask the domain controller for some information. This times out, causing git commands (using the pager?) to take ~15 - 20 seconds longer.

[seppestas]

today, for some reason, setting the HOME env var does not have any effect. From the strace output, it looks like the pager (less) is not the problem.

Digging a bit further, it looks like sh now takes a long time to start when running from a Windows process, e.g. Git for Windows or PowerShell. Weirdly, it looks that adding the --verbose flag prevents the issue?!

> get-history | fl
...
Id                 : 32
CommandLine        : & 'C:\Program Files\Git\usr\bin\sh.exe' --debug
ExecutionStatus    : Stopped
StartExecutionTime : 21/03/2024 18:17:55
EndExecutionTime   : 21/03/2024 18:18:43

Id                 : 33
CommandLine        : & 'C:\Program Files\Git\usr\bin\sh.exe' --debug --verbose
ExecutionStatus    : Stopped
StartExecutionTime : 21/03/2024 18:18:48
EndExecutionTime   : 21/03/2024 18:18:51

Id                 : 34
CommandLine        : & 'C:\Program Files\Git\usr\bin\sh.exe' --debug --verbose
ExecutionStatus    : Completed
StartExecutionTime : 21/03/2024 18:18:52
EndExecutionTime   : 21/03/2024 18:18:53

Id                 : 35
CommandLine        : & 'C:\Program Files\Git\usr\bin\sh.exe' --debug
ExecutionStatus    : Stopped
StartExecutionTime : 21/03/2024 18:18:55
EndExecutionTime   : 21/03/2024 18:19:13

Launching C:\Program Files\Git\usr\bin\sh.exe with WinDbg, it looks like it is stuck on

ModLoad: 00007fff`702c0000 00007fff`70304000   C:\WINDOWS\SYSTEM32\LOGONCLI.DLL

Enabling debug logging for the Netlogon service I can see :

03/21 18:53:57 [MISC] [28132] NetpDcGetName: <my company's domain>. similar query failed recently 7813
03/21 18:53:57 [MISC] [28132] DsGetDcName function returns 1355 (client PID=1792): Dom:EU Acct:(null) Flags: DS NETBIOS RET_DNS 
...
03/21 18:54:08 [MISC] [28132] NetpDcGetName: <my company's domain>. similar query failed recently 18641
03/21 18:54:08 [MISC] [28132] DsGetDcName function returns 1355 (client PID=1792): Dom:EU Acct:(null) Flags: DS NETBIOS RET_DNS 
03/21 18:54:13 [MISC] [36764] DsrEnumerateDomainTrusts: Called, Flags = 0x23
03/21 18:54:13 [SESSION] [36764] EU: NlSessionSetup: Try Session setup
03/21 18:54:13 [SESSION] [36764] EU: NlDiscoverDc: Start Synchronous Discovery
03/21 18:54:13 [MISC] [36764] NetpDcInitializeContext: DSGETDC_VALID_FLAGS is c1fffff1
03/21 18:54:13 [MISC] [36764] NetpDcGetName: <my company's domain>. similar query failed recently 23266
03/21 18:54:13 [CRITICAL] [36764] EU: NlDiscoverDc: Cannot find DC.
03/21 18:54:13 [CRITICAL] [36764] EU: NlSessionSetup: Session setup: cannot pick trusted DC

So it looks like:

• Git starts the C:\Program Files\Git\usr\bin\sh.exe shell (MSYS2 bash)
• sh.exe Loads the LOGONCLI.DLL (or calls some function in it, I'm not too familiar with WinDbg).
• LOGONCLI.DLL tries to talk to my domain controller and times out because it can't resolve the domain name over NetBIOS/WINS/DNS.

If I am connected to the VPN, I can see calls to DsGetDcName return some cached values. Even if I disconnect later, sh.exe no longer hangs because the name lookup still return a cached value, however there are indications the DC is no longer available.

Could the shell git uses be replaced by a different shell, e.g. a MinGW bash or Powershell?

I have a strong suspicion that the "BeyondTrust Privilege Management Service" / hook is what is actually doing the DC lookups. Would there be a way to prove this?