From 26e67a33c059b9a8017147e3851cfbde7feec529 Mon Sep 17 00:00:00 2001 From: Matthew John Cheetham Date: Thu, 17 Sep 2026 13:15:58 +0100 Subject: [PATCH] trace2: instrument Entra authentication Entra has the most branching of any authentication path in GCM: broker or not, silent or interactive, and within interactive one of three modes - each selected by some combination of user setting, stored preference, platform support and runtime availability. When someone reports that authentication did something unexpected, the answer is almost always one of those decisions, and none of them left a trace that could be correlated with timings. Assisted-by: Claude Opus 5 Signed-off-by: Matthew John Cheetham --- .../Entra/EntraAuthentication.Caching.cs | 12 +++ .../EntraAuthentication.ConfidentialClient.cs | 16 +++ .../Entra/EntraAuthentication.PublicClient.cs | 98 ++++++++++++++++--- .../Entra/EntraAuthentication.cs | 2 + 4 files changed, 114 insertions(+), 14 deletions(-) diff --git a/src/Core/Authentication/Entra/EntraAuthentication.Caching.cs b/src/Core/Authentication/Entra/EntraAuthentication.Caching.cs index 817eee49e8..e06086bbc5 100644 --- a/src/Core/Authentication/Entra/EntraAuthentication.Caching.cs +++ b/src/Core/Authentication/Entra/EntraAuthentication.Caching.cs @@ -25,11 +25,14 @@ private Task RegisterCacheAsync(IConfidentialClientApplication app) => private async Task RegisterCacheAsync(ITokenCache cache, StoragePropertiesBuilder propsBuilder) { + using var _ = Trace2.StartRegion(Trace2Category, "cache_init"); + Context.Trace.WriteLine("Configuring MSAL token cache..."); if (!PlatformUtils.IsWindows() && !PlatformUtils.IsPosix()) { string osType = PlatformUtils.GetPlatformInformation().OperatingSystemType; + Trace2.WriteData(Trace2Category, "result", "unsupported"); Context.Trace.WriteLine($"Token cache integration is not supported on {osType}."); return; } @@ -37,6 +40,7 @@ private async Task RegisterCacheAsync(ITokenCache cache, StoragePropertiesBuilde // We use the MSAL extension library to provide us consistent cache file access semantics (synchronisation, etc) // as other GCM processes, and other Microsoft developer tools such as Visual Studio. MsalCacheHelper helper = null; + string cacheResult = "ok"; try { StorageCreationProperties storageProps = propsBuilder(useLinuxFallback: false); @@ -67,6 +71,7 @@ private async Task RegisterCacheAsync(ITokenCache cache, StoragePropertiesBuilde // On Linux the SecretService/keyring might not be available so we must fall-back to a plaintext file. Context.Console.WriteWarning("using plain-text fallback token cache"); Context.Trace.WriteLine("Using fall-back plaintext token cache on Linux."); + cacheResult = "linux_fallback"; StorageCreationProperties storageProps = propsBuilder(useLinuxFallback: true); helper = await MsalCacheHelper.CreateAsync(storageProps); } @@ -74,12 +79,14 @@ private async Task RegisterCacheAsync(ITokenCache cache, StoragePropertiesBuilde if (helper is null) { + Trace2.WriteData(Trace2Category, "result", "failed"); Context.Console.WriteError("failed to set up token cache!"); Context.Trace.WriteLine("Failed to integrate with token cache!"); } else { helper.RegisterCache(cache); + Trace2.WriteData(Trace2Category, "result", cacheResult); Context.Trace.WriteLine("Token cache configured."); } } @@ -105,6 +112,7 @@ internal StorageCreationProperties CreateUserTokenCacheProps(bool useLinuxFallba // The shared cache is used by other Microsoft developer tools such as Visual Studio. if (PublicClientConfig.UseSharedCache) { + Trace2.WriteData(Trace2Category, "cache/type", "msdevtools"); Context.Trace.WriteLine("Using shared Microsoft Developer MSAL cache"); if (PlatformUtils.IsWindows()) @@ -127,6 +135,10 @@ internal StorageCreationProperties CreateUserTokenCacheProps(bool useLinuxFallba linuxAttr1 = new("MsalClientID", "Microsoft.Developer.IdentityService"); linuxAttr2 = new("Microsoft.Developer.IdentityService", "1.0.0.0"); } + else + { + Trace2.WriteData(Trace2Category, "cache/type", "gcm"); + } var builder = new StorageCreationPropertiesBuilder(cacheFileName, cacheDirectory) .WithMacKeyChain(macService, macAccount); diff --git a/src/Core/Authentication/Entra/EntraAuthentication.ConfidentialClient.cs b/src/Core/Authentication/Entra/EntraAuthentication.ConfidentialClient.cs index 09e50510ce..f59a8723f1 100644 --- a/src/Core/Authentication/Entra/EntraAuthentication.ConfidentialClient.cs +++ b/src/Core/Authentication/Entra/EntraAuthentication.ConfidentialClient.cs @@ -12,6 +12,8 @@ public partial class EntraAuthentication public async Task GetTokenForServicePrincipalAsync( string[] scopes, ServicePrincipalIdentity sp, CancellationToken ct = default) { + using var _ = Trace2.StartRegion(Trace2Category, "token_service_principal"); + Context.Trace.WriteLine($"Creating confidential client for service principal '{sp.Id}' in tenant '{sp.TenantId}'..."); var builder = ConfidentialClientApplicationBuilder.Create(sp.Id) .WithTenantId(sp.TenantId) @@ -20,11 +22,13 @@ public async Task GetTokenForServicePrincipalAsync( if (sp.Certificate is not null) { + Trace2.WriteData(Trace2Category, "credential/type", "certificate"); Context.Trace.WriteLine($"Using service principal certificate: {sp.Certificate.Thumbprint}"); builder.WithCertificate(sp.Certificate); } else if (!string.IsNullOrWhiteSpace(sp.ClientSecret)) { + Trace2.WriteData(Trace2Category, "credential/type", "secret"); Context.Trace.WriteLineSecrets("Using service principal secret: {0}", [sp.ClientSecret]); builder.WithClientSecret(sp.ClientSecret); } @@ -33,6 +37,7 @@ public async Task GetTokenForServicePrincipalAsync( throw new ArgumentException($"Service principal '{sp.Id}' must have either a certificate or client secret.", nameof(sp)); } + Trace2.WriteData(Trace2Category, "send_x5c", sp.SendX5C ? "true" : "false"); Context.Trace.WriteLine($"SendX5C is '{sp.SendX5C}'"); IConfidentialClientApplication app = builder.Build(); @@ -49,6 +54,12 @@ public async Task GetTokenForServicePrincipalAsync( public async Task GetTokenForManagedIdentityAsync( string resource, ManagedIdentity mi, CancellationToken ct = default) { + using var _ = Trace2.StartRegion(Trace2Category, "token_managed_identity"); + + // Record whether the identity is system- or user-assigned, but not the + // client or resource ID itself, which identifies a specific identity. + Trace2.WriteData(Trace2Category, "mi/kind", mi.Id.Split("://")[0]); + Context.Trace.WriteLine($"Creating confidential client for managed identity '{mi.Id}'..."); var builder = ManagedIdentityApplicationBuilder.Create(mi) .WithHttpClientFactory(_httpFactory) @@ -66,6 +77,9 @@ public async Task GetTokenForManagedIdentityAsync( public async Task GetTokenUsingWorkloadFederationAsync( string[] scopes, WorkloadFederationOptions fedOpts, CancellationToken ct = default) { + using var _ = Trace2.StartRegion(Trace2Category, "token_workload_federation"); + Trace2.WriteData(Trace2Category, "scenario", fedOpts.Scenario.ToString().ToLowerInvariant()); + Context.Trace.WriteLine( $"Creating confidential client for federation with client ID '{fedOpts.ClientId}' and tenant ID '{fedOpts.TenantId}'..."); Context.Trace.WriteLine($"Federation scenario: {fedOpts.Scenario}"); @@ -115,6 +129,8 @@ private async Task GetClientAssertion(WorkloadFederationOptions fedOpts, private async Task GetGitHubOidcToken(Uri requestUri, string audience, string requestToken) { + using var _ = Trace2.StartRegion(Trace2Category, "github_oidc"); + using HttpClient http = Context.HttpClientFactory.CreateClient(); UriBuilder ub = new UriBuilder(requestUri); diff --git a/src/Core/Authentication/Entra/EntraAuthentication.PublicClient.cs b/src/Core/Authentication/Entra/EntraAuthentication.PublicClient.cs index 47c125d382..e0d5064991 100644 --- a/src/Core/Authentication/Entra/EntraAuthentication.PublicClient.cs +++ b/src/Core/Authentication/Entra/EntraAuthentication.PublicClient.cs @@ -73,6 +73,8 @@ public partial class EntraAuthentication public async Task GetInteractionModeAsync(CancellationToken ct = default) { + using var _ = Trace2.StartRegion(Trace2Category, "get_interaction_mode"); + // Check for broker first, because if broker will be used then we always defer to that // so the interaction mode doesn't actually matter! if (IsBrokerEnabled()) @@ -86,6 +88,7 @@ public async Task GetInteractionModeAsync(CancellationToken ct GetPublicAppBuilder(out bool useBroker); if (useBroker) { + Trace2.WriteData(Trace2Category, "mode/source", "broker"); return InteractionMode.Auto; } } @@ -93,18 +96,21 @@ public async Task GetInteractionModeAsync(CancellationToken ct // Check for a stored user preference if (TryGetModePreference(out InteractionMode mode)) { + Trace2.WriteData(Trace2Category, "mode/source", "preference"); + Trace2.WriteData(Trace2Category, "mode/selected", GetModeName(mode)); return mode; } // Determine the set of available modes IList available = GetAvailableModes(); + Trace2.WriteData(Trace2Category, "mode/available", string.Join(",", available.Select(GetModeName))); // Show auth mode prompt if (Context.Settings.IsGuiPromptsEnabled && Context.SessionManager.IsDesktopSession) { if (TryFindHelperCommand(out string command, out string args)) { - var availableNames = available.Select(m => m.ToString().ToLowerInvariant()); + var availableNames = available.Select(GetModeName); var sb = new StringBuilder(args); sb.Append("select-interaction-mode"); @@ -114,6 +120,8 @@ public async Task GetInteractionModeAsync(CancellationToken ct if (result.TryGetValue("interaction_mode", out string str) && Enum.TryParse(str, ignoreCase: true, out InteractionMode choice)) { + Trace2.WriteData(Trace2Category, "mode/source", "helper"); + Trace2.WriteData(Trace2Category, "mode/selected", GetModeName(choice)); return choice; } @@ -127,32 +135,46 @@ public async Task GetInteractionModeAsync(CancellationToken ct var prompt = TerminalPrompts.CreateSelection() .Title("Select an authentication flow") .AddChoices(available, m => m.GetDisplayName()); - return await prompt.ShowAsync(Context.Console, ct); + InteractionMode selected = await prompt.ShowAsync(Context.Console, ct); + + Trace2.WriteData(Trace2Category, "mode/source", "terminal"); + Trace2.WriteData(Trace2Category, "mode/selected", GetModeName(selected)); + return selected; } public async Task> GetUserAccountsAsync(CancellationToken ct = default) { + using IDisposable region = Trace2.StartRegion(Trace2Category, "get_accounts"); + IPublicClientApplication app = GetPublicAppBuilder(out _).Build(); await RegisterCacheAsync(app); IEnumerable accounts = await app.GetAccountsAsync(); - return accounts.Select(EntraAccount.FromMsalAccount).ToList().AsReadOnly(); + var result = accounts.Select(EntraAccount.FromMsalAccount).ToList().AsReadOnly(); + + Trace2.WriteData(Trace2Category, "cached/count", result.Count); + return result; } public async Task RemoveUserAccountAsync(IEntraAccount account) { + using IDisposable region = Trace2.StartRegion(Trace2Category, "remove_account"); + IPublicClientApplication app = GetPublicAppBuilder(out _).Build(); await RegisterCacheAsync(app); IAccount msalAccount = await ResolveAccountAsync(app, account); if (msalAccount is null) { + Trace2.WriteData(Trace2Category, "was_removed", "false"); return false; } Context.Trace.WriteLine( $"Removing account '{msalAccount.HomeAccountId.Identifier}' ({msalAccount.Username}) from the cache..."); await app.RemoveAsync(msalAccount); + + Trace2.WriteData(Trace2Category, "was_removed", "true"); return true; } @@ -160,9 +182,12 @@ public async Task GetTokenForUserAsync(string[] scop IEntraAccount account = null, InteractionMode interactionMode = InteractionMode.Auto, CancellationToken ct = default) { + using var _ = Trace2.StartRegion(Trace2Category, "get_token_user"); + PublicClientApplicationBuilder builder = GetPublicAppBuilder(out bool useBroker); if (!string.IsNullOrWhiteSpace(authority)) { + Trace2.WriteData(Trace2Category, "app/authority", authority); builder.WithAuthority(authority); } @@ -187,6 +212,7 @@ public async Task GetTokenForUserAsync(string[] scop AuthenticationResult result = await GetTokenForUserSilentAsync(app, scopes, msalAccount, ct); if (result is not null) { + Trace2.WriteData(Trace2Category, "flow", "silent"); return AuthResult.FromMsalResult(result); } @@ -195,10 +221,12 @@ public async Task GetTokenForUserAsync(string[] scop // Try interactive auth if we couldn't do so with a cached account if (useBroker) { + Trace2.WriteData(Trace2Category, "flow", "broker"); result = await GetTokenForUserBrokerAsync(app, scopes, msalAccount, ct); } else { + Trace2.WriteData(Trace2Category, "flow", "interactive"); result = await GetTokenForUserInteractiveAsync(app, scopes, interactionMode, ct); } @@ -214,7 +242,12 @@ private async Task GetTokenForUserSilentAsync( return null; } - Context.Trace.WriteLine(ReferenceEquals(msalAccount, PublicClientApplication.OperatingSystemAccount) + using var _ = Trace2.StartRegion(Trace2Category, "token_silent"); + + bool isOsAccount = ReferenceEquals(msalAccount, PublicClientApplication.OperatingSystemAccount); + Trace2.WriteData(Trace2Category, "account/kind", isOsAccount ? "os_default" : "cached"); + + Context.Trace.WriteLine(isOsAccount ? "Attempting silent authentication using default operating system account" : $"Attempting silent authentication using account '{msalAccount.HomeAccountId.Identifier}'"); try @@ -225,6 +258,7 @@ private async Task GetTokenForUserSilentAsync( } catch (MsalUiRequiredException) { + Trace2.WriteData(Trace2Category, "result", "ui_required"); Context.Trace.WriteLine("Silent authentication failed; interaction required!"); return null; } @@ -233,6 +267,8 @@ private async Task GetTokenForUserSilentAsync( private async Task GetTokenForUserBrokerAsync( IPublicClientApplication app, string[] scopes, IAccount msalAccount, CancellationToken ct) { + using var _ = Trace2.StartRegion(Trace2Category, "token_broker"); + // If we don't have a specific account, let's try using the default operating system account // to silently authenticate first. if (msalAccount is null && Context.Settings.UseMsAuthDefaultAccount != false) @@ -245,10 +281,12 @@ private async Task GetTokenForUserBrokerAsync( if (Context.Settings.UseMsAuthDefaultAccount == true || await UseDefaultAccountAsync(result.Account.Username, ct)) { + Trace2.WriteData(Trace2Category, "os_account", "used"); Context.Trace.WriteLine("Using silently acquired token for default OS account."); return result; } + Trace2.WriteData(Trace2Category, "os_account", "declined"); Context.Trace.WriteLine("User opted not to use default OS account."); } } @@ -266,23 +304,30 @@ await UseDefaultAccountAsync(result.Account.Username, ct)) // Note that only interactive calls decide the mode, so the silent attempts above must // stay off the dispatcher, or they would pay to start Avalonia for nothing. // Verified against MSAL 4.85.2; re-check DesktopOsHelper.IsMacConsoleApp on upgrade. - if (PlatformUtils.IsMacOS() && !Dispatcher.MainThread.CheckAccess()) + using (Trace2.StartRegion(Trace2Category,"broker_interactive")) { - Context.Trace.WriteLine("Dispatching interactive broker authentication to main thread..."); - return await Dispatcher.MainThread.InvokeAsync( - async _ => await app.AcquireTokenInteractive(scopes) - .ExecuteAsync(ct) - ); - } + if (PlatformUtils.IsMacOS() && !Dispatcher.MainThread.CheckAccess()) + { + Trace2.WriteData(Trace2Category, "ui_dispatch", "true"); + Context.Trace.WriteLine("Dispatching interactive broker authentication to main thread..."); + return await Dispatcher.MainThread.InvokeAsync( + async _ => await app.AcquireTokenInteractive(scopes) + .ExecuteAsync(ct) + ); + } - // Already on the main thread, or on a platform whose broker does not care - return await app.AcquireTokenInteractive(scopes) - .ExecuteAsync(ct); + Trace2.WriteData(Trace2Category, "ui_dispatch", "false"); + // Already on the main thread, or on a platform whose broker does not care + return await app.AcquireTokenInteractive(scopes) + .ExecuteAsync(ct); + } } private async Task GetTokenForUserInteractiveAsync( IPublicClientApplication app, string[] scopes, InteractionMode interactionMode, CancellationToken ct) { + using var _ = Trace2.StartRegion(Trace2Category, "token_interactive"); + // Check for a stored preference if we've not been given a specific mode from the caller if (interactionMode == InteractionMode.Auto && TryGetModePreference(out InteractionMode mode)) { @@ -290,6 +335,8 @@ private async Task GetTokenForUserInteractiveAsync( interactionMode = mode; } + Trace2.WriteData(Trace2Category, "mode/requested", GetModeName(interactionMode)); + switch (interactionMode) { // Try to use the most appropriate interaction mode available @@ -307,6 +354,7 @@ private async Task GetTokenForUserInteractiveAsync( throw new InvalidOperationException("No available interaction modes."); case InteractionMode.EmbeddedWebView: + Trace2.WriteData(Trace2Category, "mode/resolved", GetModeName(InteractionMode.EmbeddedWebView)); Context.Trace.WriteLine("Performing interactive authentication via embedded webview..."); return await app.AcquireTokenInteractive(scopes) .WithUseEmbeddedWebView(true) @@ -314,6 +362,7 @@ private async Task GetTokenForUserInteractiveAsync( .ExecuteAsync(ct); case InteractionMode.SystemWebView: + Trace2.WriteData(Trace2Category, "mode/resolved", GetModeName(InteractionMode.SystemWebView)); Context.Trace.WriteLine("Performing interactive authentication via system webview..."); Context.Console.WriteInfo("opening browser to complete authentication..."); return await app.AcquireTokenInteractive(scopes) @@ -322,6 +371,7 @@ private async Task GetTokenForUserInteractiveAsync( .ExecuteAsync(ct); case InteractionMode.DeviceCode: + Trace2.WriteData(Trace2Category, "mode/resolved", GetModeName(InteractionMode.DeviceCode)); Context.Trace.WriteLine("Performing interactive authentication via device code..."); return await app.AcquireTokenWithDeviceCode(scopes, ShowDeviceCodeAsync) .ExecuteAsync(ct); @@ -334,6 +384,7 @@ private async Task GetTokenForUserInteractiveAsync( private async Task UseDefaultAccountAsync(string userName, CancellationToken ct) { ThrowIfUserInteractionDisabled(); + using var _ = Trace2.StartRegion(Trace2Category, "use_default_account"); if (Context.SessionManager.IsDesktopSession && Context.Settings.IsGuiPromptsEnabled) { @@ -371,9 +422,12 @@ private async Task UseDefaultAccountAsync(string userName, CancellationTok private async Task ResolveAccountAsync(IPublicClientApplication app, IEntraAccount account) { + using var _ = Trace2.StartRegion(Trace2Category, "resolve_account"); + // If we have been handed a wrapped MSAL account there is no need to search the cache again if (account is EntraAccount { MsalAccount: not null } wrapped) { + Trace2.WriteData(Trace2Category, "match/kind", "wrapped"); Context.Trace.WriteLine($"Account '{account.HomeAccountId}' ({account.UserName}) is already from cache."); return wrapped.MsalAccount; } @@ -381,8 +435,10 @@ private async Task ResolveAccountAsync(IPublicClientApplication app, I // Pull all account from the cache and search for the closest match, first by HomeAccountId, and then by UPN. Context.Trace.WriteLine("Getting all cached accounts..."); IReadOnlyList accounts = (await app.GetAccountsAsync()).ToList(); + Trace2.WriteData(Trace2Category, "accounts/cached_count", accounts.Count); if (accounts.Count == 0) { + Trace2.WriteData(Trace2Category, "match/kind", "none"); Context.Trace.WriteLine("No cached accounts available."); return null; } @@ -402,6 +458,7 @@ private async Task ResolveAccountAsync(IPublicClientApplication app, I $"for HomeAccountId '{account.HomeAccountId}'; using HomeAccountId."); } + Trace2.WriteData(Trace2Category, "match/kind", byId is null ? "none" : "id"); Context.Trace.WriteLine($"Matched account by ID '{byId?.HomeAccountId}' ({byId?.Username}).)"); return byId; } @@ -422,11 +479,13 @@ private async Task ResolveAccountAsync(IPublicClientApplication app, I IAccount byName = matchedByName.FirstOrDefault(); if (byName is not null) { + Trace2.WriteData(Trace2Category, "match/kind", "upn"); Context.Trace.WriteLine($"Matched account by UPN '{byName.HomeAccountId}' ({byName.Username}).)"); return byName; } } + Trace2.WriteData(Trace2Category, "match/kind", "none"); Context.Trace.WriteLine("No cached account found."); return null; } @@ -455,6 +514,7 @@ private PublicClientApplicationBuilder GetPublicAppBuilder(out bool useBroker) if (_publicBuilder is null) { Context.Trace.WriteLine("Creating public client application builder..."); + Trace2.WriteData(Trace2Category, "app/client_id", PublicClientConfig.ClientId); var builder = PublicClientApplicationBuilder.Create(PublicClientConfig.ClientId) .WithHttpClientFactory(_httpFactory) .WithTraceLogging(Context) @@ -463,6 +523,7 @@ private PublicClientApplicationBuilder GetPublicAppBuilder(out bool useBroker) // Try and configure the broker if it is enabled in user preferences, // and it is available in the current environment + string brokerStatus = "disabled"; if (Context.SessionManager.IsDesktopSession && IsBrokerEnabled()) { // Check that the app config supports the broker on this platform @@ -477,6 +538,7 @@ private PublicClientApplicationBuilder GetPublicAppBuilder(out bool useBroker) builder.WithBroker(GetBrokerOptions()); _useBroker = builder.IsBrokerAvailable(); + brokerStatus = _useBroker ? "in_use" : "unavailable"; if (_useBroker) { Context.Trace.WriteLine("Broker authentication is available."); @@ -488,6 +550,7 @@ private PublicClientApplicationBuilder GetPublicAppBuilder(out bool useBroker) // "unsigned" bundle redirect URL. if (PlatformUtils.IsMacOS()) { + Trace2.WriteData(Trace2Category, "app/redirect_url", MacBrokerRedirectUrl); Context.Trace.WriteLine($"Setting redirect URL for Mac broker to '{MacBrokerRedirectUrl}'"); builder.WithRedirectUri(MacBrokerRedirectUrl); } @@ -506,10 +569,15 @@ private PublicClientApplicationBuilder GetPublicAppBuilder(out bool useBroker) } else { + brokerStatus = "unsupported"; Context.Trace.WriteLine("Broker is not supported by the app on this platform."); } } + // Records why the broker is or is not in play, which is the first thing + // to establish when diagnosing an unexpected authentication flow. + Trace2.WriteData(Trace2Category, "broker/status", brokerStatus); + _publicBuilder = builder; } @@ -567,6 +635,8 @@ private SystemWebViewOptions GetSystemWebViewOptions() }; } + private static string GetModeName(InteractionMode mode) => mode.ToString().ToLowerInvariant(); + private IList GetAvailableModes() { var list = new List { InteractionMode.Auto }; diff --git a/src/Core/Authentication/Entra/EntraAuthentication.cs b/src/Core/Authentication/Entra/EntraAuthentication.cs index ff76197aaf..dbd27acb51 100644 --- a/src/Core/Authentication/Entra/EntraAuthentication.cs +++ b/src/Core/Authentication/Entra/EntraAuthentication.cs @@ -4,6 +4,8 @@ namespace GitCredentialManager.Authentication.Entra; public partial class EntraAuthentication : AuthenticationBase, IEntraAuthentication { + private const string Trace2Category = "entra"; + private readonly IMsalHttpClientFactory _httpFactory; public static readonly string[] AuthorityIds =