Keep being re-prompted for credentials (redux)

[kentcb]

I've reported this before, but it's come back again. I am continuing to be prompted, seemingly every time I push. I am accumulating a heap of PATs as a result.

Here's the console output with GCM_TRACE=1 and GIT_TRACE=1.

11:51:43.478036 exec-cmd.c:237          trace: resolved executable dir: C:/Program Files/Git/mingw64/bin
11:51:43.480036 git.c:703               trace: exec: git-fp
11:51:43.480036 run-command.c:663       trace: run_command: git-fp
11:51:43.484576 git.c:382               trace: alias expansion: fp => push --force-with-lease
11:51:43.484576 git.c:764               trace: exec: git push --force-with-lease
11:51:43.484576 run-command.c:663       trace: run_command: git push --force-with-lease
11:51:43.491178 exec-cmd.c:237          trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
11:51:43.493176 git.c:440               trace: built-in: git push --force-with-lease
11:51:43.494176 run-command.c:663       trace: run_command: GIT_DIR=.git git remote-https origin https://github.com/kentcb/<<redacted>>.git
11:51:43.501176 exec-cmd.c:237          trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
11:51:43.502179 git.c:703               trace: exec: git-remote-https origin https://github.com/kentcb/<<redacted>>.git
11:51:43.502179 run-command.c:663       trace: run_command: git-remote-https origin https://github.com/kentcb/<<redacted>>.git
11:51:43.510177 exec-cmd.c:237          trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
11:51:44.243591 run-command.c:663       trace: run_command: 'git credential-manager get'
11:51:44.273518 exec-cmd.c:237          trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
11:51:44.274543 git.c:703               trace: exec: git-credential-manager get
11:51:44.274543 run-command.c:663       trace: run_command: git-credential-manager get
11:51:44.400521 ...\Common.cs:744       trace: [Main] git-credential-manager (v1.19.0) 'get'
11:51:44.454548 ...\Git\Where.cs:348    trace: [FindGitInstallations] found 1 Git installation(s).
11:51:44.458546 ...Configuration.cs:222 trace: [LoadGitConfiguration] git All config read, 47 entries.
11:51:44.462546 ...\Common.cs:505       trace: [LoadOperationArguments] writeLog = 'True'.
11:51:44.463553 ...\Common.cs:318       trace: [EnableTraceLogging] trace logging enabled.
11:51:44.464545 ...\Common.cs:323       trace: [EnableTraceLogging] git local config found at 'C:\Users\Kent\Repository\<<redacted>>\.git\config'.
11:51:44.465546 ...\Common.cs:378       trace: [EnableTraceLoggingFile] trace log destination is 'C:\Users\Kent\Repository\<<redacted>>\.git'.
11:51:44.510547 ...\Common.cs:85        trace: [CreateAuthentication] detecting authority type for 'https://github.com/'.
11:51:44.524516 ...uthentication.cs:151 trace: [GetAuthentication] created GitHub authentication for 'https://github.com/'.
11:51:44.524516 ...\Common.cs:176       trace: [CreateAuthentication] authority for 'https://github.com/' is GitHub.
11:51:44.524516 ...\Common.cs:765       trace: [QueryCredentials] querying 'GitHub' for credentials.
11:51:44.557546 ...icationPrompts.cs:50 trace: [CredentialModalPrompt] prompting user for credentials for 'https://github.com/'.
11:51:57.146505 ...\Authority.cs:101    trace: [AcquireToken] server responded with Unauthorized.
11:51:57.149541 ...\Authority.cs:139    trace: [AcquireToken] two-factor app authentication code required for 'https://github.com/'.
11:51:57.151506 ...icationPrompts.cs:64 trace: [AuthenticationCodeModalPrompt] prompting user for authentication code for 'https://github.com/'.
11:52:02.722376 ...\Authority.cs:101    trace: [AcquireToken] server responded with Created.
11:52:02.723376 ...\Authority.cs:125    trace: [AcquireToken] authentication success: new personal access token for 'https://github.com/' created.
11:52:02.723376 ...uthentication.cs:219 trace: [InteractiveLogon] token acquisition for 'https://github.com/' succeeded.
11:52:03.811199 ...\Authority.cs:200    trace: [ValidateCredentials] credential validation for 'https://github.com/' succeeded.
11:52:03.811199 ...\Common.cs:873       trace: [QueryCredentials] credentials for 'https://github.com/' found.
11:52:03.812200 ...\Common.cs:709       trace: [LogEvent] GitHub credentials for 'https://github.com/' successfully retrieved.
11:52:05.347398 run-command.c:663       trace: run_command: 'git credential-manager store'
11:52:05.380399 exec-cmd.c:237          trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
11:52:05.381424 git.c:703               trace: exec: git-credential-manager store
11:52:05.381424 run-command.c:663       trace: run_command: git-credential-manager store
11:52:05.519429 ...\Common.cs:744       trace: [Main] git-credential-manager (v1.19.0) 'store'
11:52:05.573401 ...\Git\Where.cs:348    trace: [FindGitInstallations] found 1 Git installation(s).
11:52:05.578397 ...Configuration.cs:222 trace: [LoadGitConfiguration] git All config read, 47 entries.
11:52:05.581428 ...\Common.cs:505       trace: [LoadOperationArguments] writeLog = 'True'.
11:52:05.583399 ...\Common.cs:318       trace: [EnableTraceLogging] trace logging enabled.
11:52:05.583399 ...\Common.cs:323       trace: [EnableTraceLogging] git local config found at 'C:\Users\Kent\Repository\<<redacted>>\.git\config'.
11:52:05.585425 ...\Common.cs:378       trace: [EnableTraceLoggingFile] trace log destination is 'C:\Users\Kent\Repository\<<redacted>>\.git'.
11:52:05.614428 ...\Common.cs:85        trace: [CreateAuthentication] detecting authority type for 'https://PersonalAccessToken@github.com/'.
11:52:05.628428 ...uthentication.cs:151 trace: [GetAuthentication] created GitHub authentication for 'https://PersonalAccessToken@github.com/'.
11:52:05.629399 ...\Common.cs:176       trace: [CreateAuthentication] authority for 'https://PersonalAccessToken@github.com/' is GitHub.
11:52:05.629399 ...\Program.cs:526      trace: [Store] storing GitHub credentials for 'https://PersonalAccessToken@github.com/'.
11:52:05.718428 run-command.c:663       trace: run_command: git send-pack --stateless-rpc --helper-status --thin --progress --force-with-lease=refs/heads/<<redacted>>:64809174a5d2e769f679f27a3e2d02605bb0c9f8 https://github.com/kentcb/<<redacted>>.git/ --stdin
11:52:05.727427 exec-cmd.c:237          trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
11:52:05.728424 git.c:440               trace: built-in: git send-pack --stateless-rpc --helper-status --thin --progress --force-with-lease=refs/heads/<<redacted>>:64809174a5d2e769f679f27a3e2d02605bb0c9f8 https://github.com/kentcb/<<redacted>>.git/ --stdin
11:52:05.731428 run-command.c:663       trace: run_command: git pack-objects --all-progress-implied --revs --stdout --thin --delta-base-offset --progress
11:52:05.739433 exec-cmd.c:237          trace: resolved executable dir: C:/Program Files/Git/mingw64/libexec/git-core
11:52:05.741423 git.c:440               trace: built-in: git pack-objects --all-progress-implied --revs --stdout --thin --delta-base-offset --progress
Enumerating objects: 73, done.
Counting objects: 100% (73/73), done.
Delta compression using up to 8 threads
Compressing objects: 100% (42/42), done.
Writing objects: 100% (44/44), 16.44 KiB | 2.74 MiB/s, done.
Total 44 (delta 20), reused 0 (delta 0)
remote: Resolving deltas: 100% (20/20), completed with 14 local objects.
To https://github.com/kentcb/<<redacted>>.git
 + 6480917...f324515 <<redacted>> -> <<redacted>> (forced update)

Once again, credential.log is completely empty. I'd love some help to solve this painful problem once and for all. 🙏

[shiftkey]

@kentcb I haven't kept up with this project for a while, but I wanted to point out a clue from the logs.

Note the 'https://github.com/' URL used here to look for the authentication:

11:51:44.510547 ...\Common.cs:85        trace: [CreateAuthentication] detecting authority type for 'https://github.com/'.

Further down there's a 'https://PersonalAccessToken@github.com/' URL when it's storing credentials:

 trace: [Store] storing GitHub credentials for 'https://PersonalAccessToken@github.com/'.

The PersonalAccessToken string is unfamiliar to me (I see a couple of clues in the source for Microsoft authentication, which shouldn't matter here) but given this value should be the user associated with the authentication request and it's not part of the earlier check it might explain why it's always prompting for you.

You might be able to workaround it by editing the stored credential in Windows Credential Manager to drop this PersonalAccessToken (can you?) value to prevent the repetitive prompting, but that's not the whole solution.

[jcansdale]

Thanks for the suggestion @shiftkey. I'm digging into this from the support side as well and will report back with any findings.

It does look like the credential manager might be being fed with a host value of PersonalAccessToken@github.com. I don't know why that would happen. 😕

I see logs similar to what @kentcb reported if I do:

> git credential-manager fill
protocol=https
host=PersonalAccessToken@github.com
 

Any ideas?

[jcansdale]

@shiftkey,

I've dug into this some more and I think @kentcb's log does look pretty normal.

When I do a git fetch, I'm also seeing a calls to both git-credential-manager get and git-credential-manager store. In fact, since reinstalling Git for Windows I'm now seeing 2 calls to git-credential-manager store for every git fetch! This is a little worrying considering that git-credential-manager is a .NET process and expensive to spin up. 😕

15:12:44.676722 ...\Common.cs:744       trace: [Main] git-credential-manager (v1.20.0) 'get'
15:12:47.712717 ...\Common.cs:744       trace: [Main] git-credential-manager (v1.20.0) 'store'
15:12:48.637163 ...\Common.cs:744       trace: [Main] git-credential-manager (v1.20.0) 'store'

Looking at the documentation, I think it should only be calling git-credential-manager store when it falls back to using the built-in credential entry.
https://github.com/Microsoft/Git-Credential-Manager-for-Windows/wiki/How-the-Git-Credential-Managers-works

...but not for the GitHub auth?
https://github.com/Microsoft/Git-Credential-Manager-for-Windows/wiki/How-the-Git-Credential-Managers-works#github-2-factor-authentication

Something strange is going on.

[jcansdale]

I've re-read the git credential docs and think I understand what's going on:
https://git-scm.com/docs/git-credential

1. obtain credentials using git credential-manager fill
2. try doing a git clone
3. call git credential-manager store if the clone succeeded or git credential-manager delete if it failed

I'm guessing that something is going wrong when @kentcb attempts to clone and git credential-manager delete sometimes being called (nuking his credentials).

[jcansdale]

I wonder if this PR to GCMCore is related?

• Only erase credentials that match the username/password if specified
  Only erase credentials that match the username/password if specified git-ecosystem/git-credential-manager#25

[NickCraver]

Given that I can't reproduce this on 1.18.4, I'd imagine #840 is the point this behavior changed. Previously, valid credentials weren't erased aggressively.

[jcansdale]

I see @kentcb is on v1.19.0:

11:51:44.400521 ...\Common.cs:744       trace: [Main] git-credential-manager (v1.19.0) 'get'

[jcansdale]

I suspect setting the GCM_VALIDATE to 'false' would bypass this issue. When it's set to false, the credential manager won't attempt to validate the credentials every time they're used. This avoids a call to the user/subscriptions API, which I think might be failing.

See here:
https://github.com/microsoft/Git-Credential-Manager-for-Windows/blob/master/Docs/Environment.md#gcm_authority

This would just be a workaround though and the question would still be why user/subscriptions is failing (assuming it it). The Git Credential Manager Core doesn't appear to have this validating check.

[suchja]

Maybe this is totally unrelated, but I had the same problem, that suddenly personal access tokens were generated on my GitHub account and the Visual Studio GitHub extension asked for credentials frequently.
I found this issue and could see that the credential manager (in windows settings) showed an entry git:https://github.com with an account PersonalAccessToken. After looking around I figured out that I had a really old Git for Windows (version 2.17) installed (shame on me). After updating to Git for Windows (version 2.25) and pushing a new commit to GitHub there was no problem at all. Additionally the account name switched from PersonalAccessToken back to my GitHub account name.
Unfortunately I did not check the version of git-credential-manager before the update. Now I'm running 1.20.0.

Maybe this helps in some way.