diff --git a/src/Core/Authentication/Entra/EntraAuthentication.Caching.cs b/src/Core/Authentication/Entra/EntraAuthentication.Caching.cs index 817eee49e..e06086bbc 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 09e50510c..f59a8723f 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 47c125d38..e0d506499 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 ff76197aa..dbd27acb5 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 =