diff --git a/docs/design/diagnostics.md b/docs/design/diagnostics.md index 6f563762..2e812fa4 100644 --- a/docs/design/diagnostics.md +++ b/docs/design/diagnostics.md @@ -62,24 +62,62 @@ For an operation with initialized logging and telemetry, report a caught failure `ITelemetryService.TrackException`: consent can disable the remote record, while the local log remains. Use the reporting type's logger and add telemetry properties only for a specific diagnostic query. A failure that propagates to the API boundary or to the global handler is reported there; reporting it again in a lower layer records it -twice. These are rules for changes; existing catch sites do not all follow them yet. +twice. An expected condition that the code repairs, such as a token cache that +cannot be decrypted and is rebuilt at the next sign-in, is logged only: tracking it would count it among the failures. +These are rules for changes; existing catch sites do not all follow them yet. ### API boundary [HostingExtensions.AddAndConfigureProblemDetails](../../src/Infrastructure/Extensions/HostingExtensions.cs) owns -reporting for exceptions mapped to API responses. Its mappings track exceptions. Specific mappings add host -diagnostics at `Verbose`; the catch-all mapping adds diagnostics regardless of that setting. Exception details are -enabled for the UI to display and copy. Do not add duplicate tracking in each controller for exceptions that -propagate to these mappings. +reporting for exceptions mapped to API responses. Its mappings track exceptions. Specific mappings log the exception at +`Information`, which reaches the diagnostics pane only at diagnostic level `Verbose`, highlighted because it carries the +exception; the catch-all mapping does not log, because the problem details middleware already logs every response +with status 500 or higher as an error. +Exception details are enabled for the UI to display and copy. Do not add duplicate tracking in each controller for +exceptions that propagate to these mappings. ## Local logging and the diagnostics pane +There is no log file: users are asked to copy errors from the diagnostics pane, and IT support reads the Event Log. The host logger factory, created by [BootstrapContextFactory](../../src/Host/BootstrapContextFactory.cs), writes -`Warning` and above of every category, ASP.NET Core and Kestrel included, to the Windows Event Log and to -[AppEnvironment.Diagnostics](../../src/Infrastructure/AppEnvironment.cs). That store also receives explicit -`AddDiagnostics` calls, lives in memory for the whole process and has no eviction. The -[frontend logger](../../src/Scripts/controllers/logger.ts) polls `GetDiagnostics` only at diagnostic level -`Verbose`: a message can be stored without ever appearing in the pane. +`Warning` and above of every category, ASP.NET Core and Kestrel included, to the Windows Event Log and to the +[DiagnosticLogStore](../../src/Infrastructure/Diagnostics/DiagnosticLogStore.cs) read by the pane. At diagnostic level +`Verbose` the store also receives `Information` records, except from the `Microsoft` and `System` categories, whose +records below `Warning` describe every request, the pane's own polling included. +[DiagnosticLevelSwitch](../../src/Infrastructure/Diagnostics/DiagnosticLevelSwitch.cs) carries the level: the +logger factory exists before the user settings are read, so the bootstrap applies the saved level and `UpdateOptions` +applies a changed one. Code that writes to the pane logs through `ILogger`, and guards an expensive argument, such as +a serialized payload, with `IsEnabled(LogLevel.Information)`. Never log tokens or connection strings with passwords: +the pane shows them, and redaction removes only the text inside sensitive tags. + +| Store property | Consequence | +| --- | --- | +| Created with the logger factory and registered in the container as an instance | Records written before the host exists, during the bootstrap, reach the pane | +| Holds the last 1000 records and at most 8M characters of text, oldest evicted first | Memory is bounded even when records carry large payloads; a read reports how many records after its cursor it does not return | +| Each record has a sequence number; reading does not change the store | The pane keeps the cursor, so a reload reads every record held again and two readers do not take records from each other | +| A read takes a maximum count and returns the newest records | The pane asks only for as many records as it keeps | +| A record keeps the template, the placeholder values and the exception chain apart from the formatted message | The pane shows a JSON value as a tree; the formatted message is the plain text of the record | +| The exception chain holds every inner exception, those of an aggregate included, and the public properties each exception type adds, such as an error or status code | What a type writes in its `ToString` override is kept without the unstructured text; a property that exposes a secret reaches the pane, so such a type must not be logged as it is | + +The [frontend logger](../../src/Scripts/controllers/logger.ts) polls `GetDiagnostics` at every diagnostic level except +`None`. At `Basic` it shows host records of level `Warning` and above; `Verbose` adds the `Information` records. +A record of level `Warning` and above, or one that carries an exception, is highlighted. +The app's own messages, those without the `[HOST]` prefix, live only in the page, so a reload loses them. Clear +empties the view only: after a reload the pane reads the host records again from the store. + +The store keeps the original text and the pane shows it, because the user who reads it owns the data and needs the +names of the server, database or account that failed. Redaction happens where the text leaves the machine: + +| Way out | Redaction | +| --- | --- | +| A copied message; Report issue | `Utils.Obj.anonymize`: the same five tags as [SensitiveTags](../../src/Infrastructure/Telemetry/SensitiveTags.cs), plus the values of personal keys such as `email` and `serverName` | +| Host telemetry | `DefaultTelemetryProcessor`, through `SensitiveTags` | +| Crash report: saved file and the dialog's Copy | None yet: the exception text is written as `ToString()` returns it, until the crash report redesign | +| Event Log | None: it stays on the machine and IT support reads it | + +Text that leaves the machine, from the store or from an exception, applies `SensitiveTags` or the same tags. The +two tag lists, in C# and in TypeScript, change together; `SensitiveTagsTests` fails when they differ. Redaction +removes only tagged text, so copied text can still include report, server and database names. ## Telemetry consent diff --git a/src/Controllers/ApplicationController.cs b/src/Controllers/ApplicationController.cs index 16a4a648..94fc9d3b 100644 --- a/src/Controllers/ApplicationController.cs +++ b/src/Controllers/ApplicationController.cs @@ -1,14 +1,15 @@ using System; -using System.Collections.Generic; using System.Net.Mime; using System.Threading; using System.Threading.Tasks; using Hellang.Middleware.ProblemDetails; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure; using Sqlbi.Bravo.Infrastructure.Configuration; using Sqlbi.Bravo.Infrastructure.Configuration.Settings; +using Sqlbi.Bravo.Infrastructure.Diagnostics; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; using Sqlbi.Bravo.Infrastructure.Policies; @@ -29,11 +30,22 @@ public class ApplicationController : ControllerBase { private readonly ITelemetryService _telemetryService; private readonly IPolicyService _policyService; + private readonly DiagnosticLevelSwitch _diagnosticLevel; + private readonly DiagnosticLogStore _diagnosticLog; + private readonly ILogger _logger; - public ApplicationController(ITelemetryService telemetryService, IPolicyService policyService) + public ApplicationController( + ITelemetryService telemetryService, + IPolicyService policyService, + DiagnosticLevelSwitch diagnosticLevel, + DiagnosticLogStore diagnosticLog, + ILogger logger) { _telemetryService = telemetryService; _policyService = policyService; + _diagnosticLevel = diagnosticLevel; + _diagnosticLog = diagnosticLog; + _logger = logger; } /// @@ -84,8 +96,13 @@ public IActionResult UpdateOptions(BravoOptions options) return BadRequest(problem); } - - _telemetryService.TelemetryEnabled = TelemetryConsent.Resolve(_policyService.Current, UserPreferences.Current).IsEnabled; + finally + { + // A failed save can leave the settings changed in memory: the runtime follows what they hold. + var settings = UserPreferences.Current; + _diagnosticLevel.Level = settings.DiagnosticLevel; + _telemetryService.TelemetryEnabled = TelemetryConsent.Resolve(_policyService.Current, settings).IsEnabled; + } return Ok(); } @@ -146,7 +163,7 @@ public IActionResult PBIDesktopOpenPBIX(bool waitForStarted, CancellationToken c { if (ProcessHelper.OpenShellExecute(path, waitForStarted, out var processId, cancellationToken)) { - var report = PBIDesktopReport.CreateFrom(processId.Value); + var report = PBIDesktopReport.CreateFrom(processId.Value, _logger); return Ok(report); } @@ -177,29 +194,21 @@ public IActionResult FileSystemOpen(string path) } /// - /// Gets all the for the application + /// Gets the host log records added after the specified sequence number /// + /// The of the previous read, 0 to read every record held + /// The maximum number of records to return, the newest ones /// Status200OK - Success [HttpGet] [ActionName("GetDiagnostics")] [Consumes(MediaTypeNames.Application.Json)] [Produces(MediaTypeNames.Application.Json)] - [ProducesResponseType(StatusCodes.Status200OK, Type = typeof(IEnumerable))] + [ProducesResponseType(StatusCodes.Status200OK, Type = typeof(DiagnosticLogPage))] [ProducesDefaultResponseType] - public IActionResult GetDiagnostics(bool? all = null) + public IActionResult GetDiagnostics(long after = 0, int max = DiagnosticLogStore.DefaultCapacity) { - var messages = new SortedList(); - - foreach (var message in AppEnvironment.Diagnostics.Values) - { - if (all == true || message.ReadTimestamp is null) - { - message.ReadTimestamp = DateTime.UtcNow; - messages.Add(message.Timestamp, message); - } - } - - return Ok(messages.Values); + var page = _diagnosticLog.Read(after, max); + return Ok(page); } /// @@ -214,7 +223,7 @@ public IActionResult GetDiagnostics(bool? all = null) [ProducesDefaultResponseType] public async Task GetCurrentVersion(UpdateChannelType updateChannel, CancellationToken cancellationToken) { - var bravoUpdate = await CommonHelper.CheckForUpdateAsync(updateChannel, cancellationToken); + var bravoUpdate = await CommonHelper.CheckForUpdateAsync(updateChannel, _logger, cancellationToken); if (bravoUpdate.IsNewerVersion) System.Media.SystemSounds.Beep.Play(); diff --git a/src/Controllers/AuthenticationController.cs b/src/Controllers/AuthenticationController.cs index 15729844..b2e0ea3e 100644 --- a/src/Controllers/AuthenticationController.cs +++ b/src/Controllers/AuthenticationController.cs @@ -1,13 +1,10 @@ using System; using System.Net.Mime; -using System.Text.Json; using System.Threading; using System.Threading.Tasks; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc; -using Sqlbi.Bravo.Infrastructure; using Sqlbi.Bravo.Infrastructure.PowerBI.Cloud; -using Sqlbi.Bravo.Models; using Sqlbi.Bravo.Models.Authentication; using Sqlbi.Bravo.Services; @@ -44,9 +41,6 @@ public async Task GetEnvironmentsAsync( request.Email, cancellationToken); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(AuthenticationController)}.{nameof(GetEnvironmentsAsync)}", JsonSerializer.Serialize(environments)); - var response = new GetEnvironmentsResponse(environments); return Ok(response); } diff --git a/src/Controllers/TemplateDevelopmentController.cs b/src/Controllers/TemplateDevelopmentController.cs index c7c62b2d..ecaa4cc5 100644 --- a/src/Controllers/TemplateDevelopmentController.cs +++ b/src/Controllers/TemplateDevelopmentController.cs @@ -4,6 +4,7 @@ using System.Threading; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Helpers; using Sqlbi.Bravo.Models; using Sqlbi.Bravo.Models.AnalyzeModel; @@ -26,11 +27,13 @@ public class TemplateDevelopmentController : ControllerBase private readonly ITemplateDevelopmentService _templateDevelopmentService; private readonly IAnalyzeModelService _analyzeModelService; + private readonly ILogger _logger; - public TemplateDevelopmentController(ITemplateDevelopmentService templateDevelopmentService, IAnalyzeModelService analyzeModelService) + public TemplateDevelopmentController(ITemplateDevelopmentService templateDevelopmentService, IAnalyzeModelService analyzeModelService, ILogger logger) { _templateDevelopmentService = templateDevelopmentService; _analyzeModelService = analyzeModelService; + _logger = logger; } /// @@ -175,7 +178,7 @@ public IActionResult PBIDesktopOpenPBIX(string path, bool waitForStarted, Cancel { if (ProcessHelper.OpenShellExecute(path, waitForStarted, out var processId, cancellationToken)) { - var report = PBIDesktopReport.CreateFrom(processId.Value); + var report = PBIDesktopReport.CreateFrom(processId.Value, _logger); return Ok(report); } return Forbid(); diff --git a/src/Host/BootstrapContext.cs b/src/Host/BootstrapContext.cs index 84d4f818..d1e8dc4b 100644 --- a/src/Host/BootstrapContext.cs +++ b/src/Host/BootstrapContext.cs @@ -1,6 +1,7 @@ using System; using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Configuration.Settings; +using Sqlbi.Bravo.Infrastructure.Diagnostics; using Sqlbi.Bravo.Infrastructure.Policies; using Sqlbi.Bravo.Infrastructure.Telemetry; @@ -19,12 +20,16 @@ internal sealed class BootstrapContext : IDisposable internal BootstrapContext( ILoggerFactory loggerFactory, + DiagnosticLevelSwitch diagnosticLevel, + DiagnosticLogStore diagnosticLog, IPolicyService policyService, IUserSettings settings, ITelemetryService telemetry, IDisposable? exceptionHandlerAttachment = null) { LoggerFactory = loggerFactory; + DiagnosticLevel = diagnosticLevel; + DiagnosticLog = diagnosticLog; PolicyService = policyService; Settings = settings; Telemetry = telemetry; @@ -32,6 +37,8 @@ internal BootstrapContext( } public ILoggerFactory LoggerFactory { get; } + public DiagnosticLevelSwitch DiagnosticLevel { get; } + public DiagnosticLogStore DiagnosticLog { get; } public IPolicyService PolicyService { get; } public IUserSettings Settings { get; } public ITelemetryService Telemetry { get; } diff --git a/src/Host/BootstrapContextFactory.cs b/src/Host/BootstrapContextFactory.cs index 0fe3c29e..2fdc2e36 100644 --- a/src/Host/BootstrapContextFactory.cs +++ b/src/Host/BootstrapContextFactory.cs @@ -10,12 +10,16 @@ namespace Sqlbi.Bravo.Host; internal sealed partial class BootstrapContextFactory( ILoggerFactory loggerFactory, + DiagnosticLevelSwitch diagnosticLevel, + DiagnosticLogStore diagnosticLog, IPolicyServiceFactory policyFactory, IUserSettingsServiceFactory settingsFactory, ITelemetryServiceFactory telemetryFactory, UnhandledExceptionHandler exceptionHandler) { private readonly ILoggerFactory _loggerFactory = loggerFactory; + private readonly DiagnosticLevelSwitch _diagnosticLevel = diagnosticLevel; + private readonly DiagnosticLogStore _diagnosticLog = diagnosticLog; private readonly IPolicyServiceFactory _policyFactory = policyFactory; private readonly IUserSettingsServiceFactory _settingsFactory = settingsFactory; private readonly ITelemetryServiceFactory _telemetryFactory = telemetryFactory; @@ -23,11 +27,15 @@ internal sealed partial class BootstrapContextFactory( public static BootstrapContext CreateDefault(UnhandledExceptionHandler exceptionHandler) { - var loggerFactory = CreateLoggerFactory(); + var diagnosticLevel = new DiagnosticLevelSwitch(); + var diagnosticLog = new DiagnosticLogStore(); + var loggerFactory = CreateLoggerFactory(diagnosticLevel, diagnosticLog); try { var factory = new BootstrapContextFactory( loggerFactory, + diagnosticLevel, + diagnosticLog, new PolicyServiceFactory(), new UserSettingsServiceFactory(), new TelemetryServiceFactory(), @@ -50,22 +58,22 @@ public BootstrapContext Create() { var policies = CreatePolicies(); var settings = CreateSettings(); + _diagnosticLevel.Level = settings.DiagnosticLevel; var consent = TelemetryConsent.Resolve(policies.Current, settings); var telemetry = CreateTelemetry(consent.IsEnabled); var exceptionHandlerAttachment = _exceptionHandler.AttachServices(_loggerFactory, telemetry); - return new BootstrapContext(_loggerFactory, policies, settings, telemetry, exceptionHandlerAttachment); + return new BootstrapContext(_loggerFactory, _diagnosticLevel, _diagnosticLog, policies, settings, telemetry, exceptionHandlerAttachment); } - private static ILoggerFactory CreateLoggerFactory() + private static ILoggerFactory CreateLoggerFactory(DiagnosticLevelSwitch diagnosticLevel, DiagnosticLogStore diagnosticLog) { return LoggerFactory.Create((builder) => { builder.AddEventSourceLogger(); builder.AddBravoEventLog(); - builder.AddDiagnosticMessages(); - builder.AddFilter((level) => level >= LogLevel.Warning); + builder.AddBravoDiagnosticLog(diagnosticLog, diagnosticLevel, TimeProvider.System); #if DEBUG builder.AddConsole(); builder.AddDebug(); diff --git a/src/Host/BravoLoggingBuilderExtensions.cs b/src/Host/BravoLoggingBuilderExtensions.cs index 36f421a5..2406023a 100644 --- a/src/Host/BravoLoggingBuilderExtensions.cs +++ b/src/Host/BravoLoggingBuilderExtensions.cs @@ -1,5 +1,7 @@ -using Microsoft.Extensions.Logging; +using System; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.EventLog; +using Sqlbi.Bravo.Infrastructure.Diagnostics; namespace Sqlbi.Bravo.Host; @@ -13,4 +15,20 @@ public static ILoggingBuilder AddBravoEventLog(this ILoggingBuilder builder) return builder; } + + public static ILoggingBuilder AddBravoDiagnosticLog( + this ILoggingBuilder builder, + DiagnosticLogStore store, + DiagnosticLevelSwitch levelSwitch, + TimeProvider timeProvider) + { + builder.AddDiagnosticLog(store, timeProvider); + builder.AddFilter((category, level) => level >= levelSwitch.MinimumLevel); + + // Framework records below Warning describe every request, the pane's own polling included. + builder.AddFilter("Microsoft", LogLevel.Warning); + builder.AddFilter("System", LogLevel.Warning); + + return builder; + } } diff --git a/src/Host/BravoServiceCollectionExtensions.cs b/src/Host/BravoServiceCollectionExtensions.cs index 18db3175..417ce6c6 100644 --- a/src/Host/BravoServiceCollectionExtensions.cs +++ b/src/Host/BravoServiceCollectionExtensions.cs @@ -67,6 +67,8 @@ private static IServiceCollection AddBootstrapServices(this IServiceCollection s // Replace the default ILoggerFactory registered by the WebApplicationBuilder services.Replace(ServiceDescriptor.Singleton(bootstrap.LoggerFactory)); + services.AddSingleton(bootstrap.DiagnosticLevel); + services.AddSingleton(bootstrap.DiagnosticLog); services.AddSingleton(bootstrap.PolicyService); services.AddSingleton(bootstrap.Settings); diff --git a/src/Infrastructure/AppEnvironment.cs b/src/Infrastructure/AppEnvironment.cs index b35f183e..680af188 100644 --- a/src/Infrastructure/AppEnvironment.cs +++ b/src/Infrastructure/AppEnvironment.cs @@ -1,5 +1,4 @@ using System; -using System.Collections.Concurrent; using System.Diagnostics; using System.Drawing; using System.IO; @@ -66,7 +65,6 @@ static AppEnvironment() MsalTokenCacheFilePath = Path.Combine(ApplicationDataPath, ".msalcache"); WebView2VersionInfo = WebView2Helper.GetRuntimeVersionInfo(); - Diagnostics = new ConcurrentDictionary(); DefaultJsonOptions = new(JsonSerializerDefaults.Web) { MaxDepth = 32 }; // see Microsoft.AspNetCore.Mvc.JsonOptions.JsonSerializerOptions } @@ -124,23 +122,6 @@ public static RegistryKey? ApplicationInstallerRegistryHKey public static bool IsWebView2RuntimeInstalled => WebView2VersionInfo is not null; - public static bool IsDiagnosticLevelVerbose => UserPreferences.Current.DiagnosticLevel == DiagnosticLevelType.Verbose; - - public static ConcurrentDictionary Diagnostics { get; } - - public static void AddDiagnostics(string name, Exception exception, DiagnosticMessageSeverity severity = DiagnosticMessageSeverity.Error) - { - var content = exception.ToString(); - AddDiagnostics(DiagnosticMessageType.Text, name, content, severity); - } - - public static void AddDiagnostics(DiagnosticMessageType type, string name, string content, DiagnosticMessageSeverity severity = DiagnosticMessageSeverity.None) - { - var message = DiagnosticMessage.Create(type, severity, name, content); - - _ = Diagnostics.TryAdd(message, message); - } - private static AppDeploymentMode GetDeploymentMode() { if (DesktopBridgeHelper.IsRunningAsMsixPackage()) diff --git a/src/Infrastructure/AppWindow.Log.cs b/src/Infrastructure/AppWindow.Log.cs new file mode 100644 index 00000000..687e7de6 --- /dev/null +++ b/src/Infrastructure/AppWindow.Log.cs @@ -0,0 +1,18 @@ +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure; + +internal partial class AppWindow +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "WebView2 additional browser arguments: {Arguments}")] + private partial void LogBrowserArguments(string? arguments); + + [LoggerMessage(EventId = 2, Level = LogLevel.Information, Message = "Environment diagnostics: {Diagnostics}")] + private partial void LogEnvironmentDiagnostics(string diagnostics); + + [LoggerMessage(EventId = 3, Level = LogLevel.Information, Message = "Startup message created from the command line: {StartupMessage}")] + private partial void LogStartupMessageCreated(string startupMessage); + + [LoggerMessage(EventId = 4, Level = LogLevel.Information, Message = "Posting the web message: {WebMessage}")] + private partial void LogWebMessagePosting(string? webMessage); +} diff --git a/src/Infrastructure/AppWindow.cs b/src/Infrastructure/AppWindow.cs index d05b825d..d4e49e05 100644 --- a/src/Infrastructure/AppWindow.cs +++ b/src/Infrastructure/AppWindow.cs @@ -8,6 +8,7 @@ using System.Threading; using System.Windows.Forms; using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; using Microsoft.Web.WebView2.Core; using Microsoft.Web.WebView2.WinForms; @@ -47,17 +48,20 @@ internal partial class AppWindow : Form private readonly WebView2ProxyAuthHandler _proxyAuthHandler; private readonly Color _startupThemeColor; private readonly IPolicyService _policyService; + private readonly ILogger _logger; public AppWindow( IInstanceEvents applicationInstance, IServerAddressProvider serverAddressProvider, IOptions startupSettingsOptionsAccessor, - IPolicyService policyService) + IPolicyService policyService, + ILogger logger) { _applicationInstance = applicationInstance; _serverAddressProvider = serverAddressProvider; _startupSettingsOptionsAccessor = startupSettingsOptionsAccessor; _policyService = policyService; + _logger = logger; _proxyAuthHandler = new WebView2ProxyAuthHandler(WebProxyWrapper.Current); _startupThemeColor = ThemeHelper.ShouldUseDarkMode(UserPreferences.Current.Theme) ? AppEnvironment.ThemeColorDark : AppEnvironment.ThemeColorLight; @@ -101,8 +105,7 @@ private async void InitializeWebViewAsync() { /* ICoreWebView2EnvironmentOptions */ options.AdditionalBrowserArguments = WebView2Helper.GetProxyArguments(UserPreferences.Current.Proxy, WebProxyWrapper.Current.DefaultSystemProxy); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Text, name: $"{nameof(AppWindow)}.{nameof(InitializeWebViewAsync)}.{nameof(options.AdditionalBrowserArguments)}", content: options.AdditionalBrowserArguments); + LogBrowserArguments(options.AdditionalBrowserArguments); } var environment = await CoreWebView2Environment.CreateAsync(browserExecutableFolder: null, userDataFolder: AppEnvironment.ApplicationTempPath, options); { @@ -185,10 +188,10 @@ private void OnFormLoad(object? sender, EventArgs e) _applicationInstance.ActivationRequested += OnActivationRequestedRestoreWindowToForeground; - if (AppEnvironment.IsDiagnosticLevelVerbose) + if (_logger.IsEnabled(LogLevel.Information)) { var content = EnvironmentDiagnosticsCollector.Collect(); - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(AppWindow)}.{nameof(EnvironmentDiagnostics)}", content: JsonSerializer.Serialize(content)); + LogEnvironmentDiagnostics(JsonSerializer.Serialize(content)); } } @@ -312,6 +315,7 @@ private void OnActivationRequestedSendStartupWebMessage(object? sender, Instance ProcessHelper.InvokeOnUIThread(this, () => { var webMessageString = e.StartupMessage.ToWebMessageString(); + LogWebMessagePosting(webMessageString); WebView.CoreWebView2.PostWebMessageAsString(webMessageString); }); } @@ -356,10 +360,13 @@ private void SendAppStartupWebMessage() { var startupMessage = AppInstanceStartupMessage.CreateFrom(startupSettings); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(AppInstanceStartupMessage)}.{nameof(AppInstanceStartupMessage.CreateFrom)}", content: JsonSerializer.Serialize(startupMessage)); + if (_logger.IsEnabled(LogLevel.Information)) + { + LogStartupMessageCreated(JsonSerializer.Serialize(startupMessage)); + } var startupMessageString = startupMessage.ToWebMessageString(); + LogWebMessagePosting(startupMessageString); WebView.CoreWebView2.PostWebMessageAsString(startupMessageString); } @@ -369,8 +376,5 @@ private void SendAppStartupWebMessage() private void WebViewLog(string message) { WebView.CoreWebView2.ExecuteScriptAsync($"console.log('[WEBVIEW]{message}');"); - - //if (AppEnvironment.IsDiagnosticLevelVerbose) - // AppEnvironment.AddDiagnostics(DiagnosticMessageType.Text, name: $"{ nameof(AppWindow) }.{ nameof(WebView2) }", content: message); } } diff --git a/src/Infrastructure/Diagnostics/DiagnosticLevelSwitch.cs b/src/Infrastructure/Diagnostics/DiagnosticLevelSwitch.cs new file mode 100644 index 00000000..1fe11a68 --- /dev/null +++ b/src/Infrastructure/Diagnostics/DiagnosticLevelSwitch.cs @@ -0,0 +1,24 @@ +using Microsoft.Extensions.Logging; +using Sqlbi.Bravo.Infrastructure.Configuration.Settings; + +namespace Sqlbi.Bravo.Infrastructure.Diagnostics; + +/// +/// Holds the diagnostic level chosen by the user, which sets the lowest level written to the diagnostics pane. +/// +/// +/// The logger factory exists before the user settings are read, so the level is applied once they are loaded and +/// again whenever the user changes it. +/// +public sealed class DiagnosticLevelSwitch(DiagnosticLevelType level = UserSettings.DefaultDiagnosticLevel) +{ + private volatile DiagnosticLevelType _level = level; + + public DiagnosticLevelType Level + { + get => _level; + set => _level = value; + } + + public LogLevel MinimumLevel => _level == DiagnosticLevelType.Verbose ? LogLevel.Information : LogLevel.Warning; +} diff --git a/src/Infrastructure/Diagnostics/DiagnosticLogBuilderExtensions.cs b/src/Infrastructure/Diagnostics/DiagnosticLogBuilderExtensions.cs new file mode 100644 index 00000000..27b3387d --- /dev/null +++ b/src/Infrastructure/Diagnostics/DiagnosticLogBuilderExtensions.cs @@ -0,0 +1,20 @@ +using System; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.Diagnostics; + +internal static class DiagnosticLogBuilderExtensions +{ + public static ILoggingBuilder AddDiagnosticLog( + this ILoggingBuilder builder, + DiagnosticLogStore store, + TimeProvider timeProvider) + { + var provider = new DiagnosticLogProvider(store, timeProvider); + builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton(provider)); + + return builder; + } +} diff --git a/src/Infrastructure/Diagnostics/DiagnosticLogEntry.cs b/src/Infrastructure/Diagnostics/DiagnosticLogEntry.cs new file mode 100644 index 00000000..c1517d6f --- /dev/null +++ b/src/Infrastructure/Diagnostics/DiagnosticLogEntry.cs @@ -0,0 +1,22 @@ +using System; +using System.Collections.Generic; +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.Diagnostics; + +/// +/// A log record kept for the diagnostics pane. +/// +/// The message template, when the record has . +/// The values of the template placeholders, as text. +/// The exception and its inner exceptions, outermost first, depth first. +public sealed record DiagnosticLogEntry( + DateTimeOffset Timestamp, + LogLevel Level, + string Category, + int EventId, + string? EventName, + string Message, + string? Template, + IReadOnlyDictionary? Properties, + IReadOnlyList? Exception); diff --git a/src/Infrastructure/Diagnostics/DiagnosticLogException.cs b/src/Infrastructure/Diagnostics/DiagnosticLogException.cs new file mode 100644 index 00000000..d5cd6e6e --- /dev/null +++ b/src/Infrastructure/Diagnostics/DiagnosticLogException.cs @@ -0,0 +1,105 @@ +using System; +using System.Collections.Generic; +using System.Reflection; + +namespace Sqlbi.Bravo.Infrastructure.Diagnostics; + +/// +/// One exception of the chain kept with a . +/// +/// +/// The public properties the exception type adds to , such as an error code or a status +/// code, which the type usually writes in its override. +/// +public sealed record DiagnosticLogException( + string Type, + string Message, + string? StackTrace, + IReadOnlyDictionary? Details) +{ + public static IReadOnlyList? CreateChain(Exception? exception) + { + if (exception is null) + { + return null; + } + + var chain = new List(); + var pending = new Stack(); + pending.Push(exception); + + while (pending.Count > 0) + { + var current = pending.Pop(); + chain.Add(Create(current)); + + // An aggregate keeps every inner exception, not only the first one that InnerException returns. + if (current is AggregateException aggregate) + { + for (var index = aggregate.InnerExceptions.Count - 1; index >= 0; index--) + { + pending.Push(aggregate.InnerExceptions[index]); + } + } + else if (current.InnerException is not null) + { + pending.Push(current.InnerException); + } + } + + return chain; + } + + private static DiagnosticLogException Create(Exception exception) + { + var type = exception.GetType(); + var typeName = type.FullName ?? type.Name; + + return new DiagnosticLogException(typeName, exception.Message, exception.StackTrace, ReadDetails(exception)); + } + + private static Dictionary? ReadDetails(Exception exception) + { + var details = new Dictionary(); + + foreach (var property in exception.GetType().GetProperties(BindingFlags.Public | BindingFlags.Instance)) + { + if (!IsDetail(property)) + { + continue; + } + + try + { + var value = property.GetValue(exception); + if (value is not null) + { + details[property.Name] = value.ToString(); + } + } + catch (Exception) + { + // A property that fails to read is left out; the rest of the record is still useful. + } + } + + if (details.Count == 0) + { + return null; + } + + return details; + } + + private static bool IsDetail(PropertyInfo property) + { + if (property.DeclaringType == typeof(Exception) || property.GetIndexParameters().Length > 0) + { + return false; + } + + // Inner exceptions are already entries of the chain. + var propertyType = property.PropertyType; + return !typeof(Exception).IsAssignableFrom(propertyType) && !typeof(IEnumerable).IsAssignableFrom(propertyType); + } +} diff --git a/src/Infrastructure/Diagnostics/DiagnosticLogPage.cs b/src/Infrastructure/Diagnostics/DiagnosticLogPage.cs new file mode 100644 index 00000000..02323291 --- /dev/null +++ b/src/Infrastructure/Diagnostics/DiagnosticLogPage.cs @@ -0,0 +1,10 @@ +using System.Collections.Generic; + +namespace Sqlbi.Bravo.Infrastructure.Diagnostics; + +/// +/// The records added after a sequence number, read by the diagnostics pane. +/// +/// The sequence number to pass to the next read. +/// Records added after the requested sequence that the read does not return: evicted, or beyond its maximum count. +public sealed record DiagnosticLogPage(IReadOnlyList Entries, long LastSequence, long DroppedCount); diff --git a/src/Infrastructure/Diagnostics/DiagnosticLogProvider.cs b/src/Infrastructure/Diagnostics/DiagnosticLogProvider.cs new file mode 100644 index 00000000..522d62c5 --- /dev/null +++ b/src/Infrastructure/Diagnostics/DiagnosticLogProvider.cs @@ -0,0 +1,87 @@ +using System; +using System.Collections.Generic; +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.Diagnostics; + +/// +/// Writes log records to the read by the diagnostics pane. +/// +[ProviderAlias("Diagnostics")] +internal sealed class DiagnosticLogProvider(DiagnosticLogStore store, TimeProvider timeProvider) : ILoggerProvider +{ + private readonly DiagnosticLogStore _store = store; + private readonly TimeProvider _timeProvider = timeProvider; + + public ILogger CreateLogger(string categoryName) => new DiagnosticLogger(categoryName, _store, _timeProvider); + + public void Dispose() + { + } + + private sealed class DiagnosticLogger(string categoryName, DiagnosticLogStore store, TimeProvider timeProvider) : ILogger + { + private const string OriginalFormatKey = "{OriginalFormat}"; + + private readonly string _categoryName = categoryName; + private readonly DiagnosticLogStore _store = store; + private readonly TimeProvider _timeProvider = timeProvider; + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + { + try + { + var (template, properties) = ReadProperties(state); + var entry = new DiagnosticLogEntry( + _timeProvider.GetUtcNow(), + logLevel, + _categoryName, + eventId.Id, + eventId.Name, + formatter(state, exception), + template, + properties, + DiagnosticLogException.CreateChain(exception)); + + _store.Add(entry); + } + catch (Exception) + { + // A sink failure does not propagate to the caller of ILogger.Log. + } + } + + private static (string? Template, IReadOnlyDictionary? Properties) ReadProperties(TState state) + { + if (state is not IReadOnlyList> values) + { + return (null, null); + } + + string? template = null; + var properties = new Dictionary(); + foreach (var (key, value) in values) + { + if (key == OriginalFormatKey) + { + template = value as string; + } + else + { + properties[key] = value?.ToString(); + } + } + + if (properties.Count == 0) + { + return (null, null); + } + + return (template, properties); + } + } +} diff --git a/src/Infrastructure/Diagnostics/DiagnosticLogStore.cs b/src/Infrastructure/Diagnostics/DiagnosticLogStore.cs new file mode 100644 index 00000000..d1ab8b04 --- /dev/null +++ b/src/Infrastructure/Diagnostics/DiagnosticLogStore.cs @@ -0,0 +1,116 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; + +namespace Sqlbi.Bravo.Infrastructure.Diagnostics; + +/// +/// Keeps the most recent log records in memory for the diagnostics pane, oldest evicted first. +/// +/// +/// Readers keep their own cursor: reading does not change the store, so a reload of the pane reads the same records. +/// The store is bounded both by the number of records and by their text, because a single record can carry a +/// serialized payload of several megabytes. +/// +public sealed class DiagnosticLogStore +{ + public const int DefaultCapacity = 1000; + public const long DefaultCharacterBudget = 8 * 1024 * 1024; + + private readonly Queue _slots = new(); + private readonly Lock _lock = new(); + private readonly int _capacity; + private readonly long _characterBudget; + private long _lastSequence; + private long _characters; + + public DiagnosticLogStore(int capacity = DefaultCapacity, long characterBudget = DefaultCharacterBudget) + { + ArgumentOutOfRangeException.ThrowIfNegativeOrZero(capacity); + ArgumentOutOfRangeException.ThrowIfNegativeOrZero(characterBudget); + + _capacity = capacity; + _characterBudget = characterBudget; + } + + public void Add(DiagnosticLogEntry entry) + { + var size = CountCharacters(entry); + + lock (_lock) + { + _lastSequence++; + _slots.Enqueue(new Slot(_lastSequence, entry, size)); + _characters += size; + + // The newest record is kept even when it alone exceeds the budget. + while (_slots.Count > _capacity || (_characters > _characterBudget && _slots.Count > 1)) + { + var evicted = _slots.Dequeue(); + _characters -= evicted.Size; + } + } + } + + /// + /// Reads the records added after , at most the newest of them. + /// + public DiagnosticLogPage Read(long after, int maxCount = int.MaxValue) + { + var cursor = Math.Max(after, 0); + var limit = Math.Max(maxCount, 0); + + lock (_lock) + { + var firstHeld = _slots.Count > 0 ? _slots.Peek().Sequence : _lastSequence + 1; + var evictedCount = Math.Max(firstHeld - (cursor + 1), 0); + var heldCount = Math.Max(_lastSequence - Math.Max(cursor, firstHeld - 1), 0); + var skippedCount = Math.Max(heldCount - limit, 0); + + var entries = _slots + .Where((slot) => slot.Sequence > cursor) + .Skip((int)skippedCount) + .Select((slot) => slot.Entry) + .ToArray(); + + return new DiagnosticLogPage(entries, _lastSequence, evictedCount + skippedCount); + } + } + + private static long CountCharacters(DiagnosticLogEntry entry) + { + long count = entry.Category.Length + entry.Message.Length + (entry.Template?.Length ?? 0); + + count += CountCharacters(entry.Properties); + + if (entry.Exception is not null) + { + foreach (var exception in entry.Exception) + { + count += exception.Type.Length + exception.Message.Length + (exception.StackTrace?.Length ?? 0); + count += CountCharacters(exception.Details); + } + } + + return count; + } + + private static long CountCharacters(IReadOnlyDictionary? values) + { + if (values is null) + { + return 0; + } + + long count = 0; + foreach (var (key, value) in values) + { + count += key.Length + (value?.Length ?? 0); + } + + return count; + } + + private readonly record struct Slot(long Sequence, DiagnosticLogEntry Entry, long Size); +} diff --git a/src/Infrastructure/Diagnostics/DiagnosticMessageLogger.cs b/src/Infrastructure/Diagnostics/DiagnosticMessageLogger.cs deleted file mode 100644 index 563521bd..00000000 --- a/src/Infrastructure/Diagnostics/DiagnosticMessageLogger.cs +++ /dev/null @@ -1,53 +0,0 @@ -using System; -using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.DependencyInjection.Extensions; -using Microsoft.Extensions.Logging; -using Sqlbi.Bravo.Models; - -namespace Sqlbi.Bravo.Infrastructure.Diagnostics; - -internal sealed class DiagnosticMessageLogger(string categoryName) : ILogger -{ - private readonly string _categoryName = categoryName; - - public IDisposable? BeginScope(TState state) where TState : notnull => null; - - public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None; - - public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) - { - var content = formatter(state, exception); - - if (exception is not null) - content = $"{content}{Environment.NewLine}{exception}"; - - try - { - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Text, _categoryName, content, GetSeverity(logLevel)); - } - catch (Exception) - { - // A sink failure does not propagate to the caller of ILogger.Log. - } - } - - private static DiagnosticMessageSeverity GetSeverity(LogLevel logLevel) - { - return logLevel switch - { - LogLevel.Critical or LogLevel.Error => DiagnosticMessageSeverity.Error, - LogLevel.Warning => DiagnosticMessageSeverity.Warning, - _ => DiagnosticMessageSeverity.None, - }; - } -} - -internal static class DiagnosticMessageLoggerExtensions -{ - public static ILoggingBuilder AddDiagnosticMessages(this ILoggingBuilder builder) - { - builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); - - return builder; - } -} diff --git a/src/Infrastructure/Diagnostics/DiagnosticMessageLoggerProvider.cs b/src/Infrastructure/Diagnostics/DiagnosticMessageLoggerProvider.cs deleted file mode 100644 index 1cdae225..00000000 --- a/src/Infrastructure/Diagnostics/DiagnosticMessageLoggerProvider.cs +++ /dev/null @@ -1,16 +0,0 @@ -using Microsoft.Extensions.Logging; - -namespace Sqlbi.Bravo.Infrastructure.Diagnostics; - -/// -/// Writes log records to , the channel the user interface polls. -/// -[ProviderAlias("Diagnostics")] -internal sealed class DiagnosticMessageLoggerProvider : ILoggerProvider -{ - public ILogger CreateLogger(string categoryName) => new DiagnosticMessageLogger(categoryName); - - public void Dispose() - { - } -} diff --git a/src/Infrastructure/Extensions/HostingExtensions.Log.cs b/src/Infrastructure/Extensions/HostingExtensions.Log.cs new file mode 100644 index 00000000..92f03402 --- /dev/null +++ b/src/Infrastructure/Extensions/HostingExtensions.Log.cs @@ -0,0 +1,13 @@ +using System; +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.Extensions; + +internal static partial class HostingExtensions +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "The request model is not valid: {ValidationProblem}")] + private static partial void LogRequestModelInvalid(ILogger logger, string validationProblem); + + [LoggerMessage(EventId = 2, Level = LogLevel.Information, Message = "The request failed with an exception mapped to a problem details response.")] + private static partial void LogExceptionMapped(ILogger logger, Exception exception); +} diff --git a/src/Infrastructure/Extensions/HostingExtensions.cs b/src/Infrastructure/Extensions/HostingExtensions.cs index ebc91b47..73dd6ca5 100644 --- a/src/Infrastructure/Extensions/HostingExtensions.cs +++ b/src/Infrastructure/Extensions/HostingExtensions.cs @@ -11,6 +11,7 @@ using Microsoft.AspNetCore.Mvc; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Logging; using Microsoft.Identity.Client; using Sqlbi.Bravo.Infrastructure.Authentication; using Sqlbi.Bravo.Infrastructure.Helpers; @@ -20,7 +21,7 @@ namespace Sqlbi.Bravo.Infrastructure.Extensions; -internal static class HostingExtensions +internal static partial class HostingExtensions { public static IMvcBuilder AddAndConfigureControllers(this IServiceCollection services) { @@ -38,7 +39,7 @@ public static IMvcBuilder AddAndConfigureControllers(this IServiceCollection ser apiOptions.InvalidModelStateResponseFactory = (context) => { var content = JsonSerializer.Serialize(new ValidationProblemDetails(context.ModelState)); - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(MvcCoreMvcBuilderExtensions.ConfigureApiBehaviorOptions)}.{nameof(apiOptions.InvalidModelStateResponseFactory)}", content, DiagnosticMessageSeverity.Error); + LogRequestModelInvalid(GetLogger(context.HttpContext), content); // Invoke the defaultFactory delegate to preserve the default behavior return defaultFactory(context); @@ -129,10 +130,7 @@ public static IServiceCollection AddAndConfigureProblemDetails(this IServiceColl options.Map((context, exception) => { - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(name: nameof(BravoException), exception); - - context.RequestServices.GetRequiredService().TrackException(exception); + ReportMappedException(context, exception); var problemDetailsFactory = context.RequestServices.GetRequiredService(); var problemDetails = problemDetailsFactory.CreateProblemDetails(context, @@ -145,10 +143,7 @@ public static IServiceCollection AddAndConfigureProblemDetails(this IServiceColl options.Map((context, exception) => { - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(name: nameof(MsalException), exception); - - context.RequestServices.GetRequiredService().TrackException(exception); + ReportMappedException(context, exception); var problemDetailsFactory = context.RequestServices.GetRequiredService(); var problemDetails = problemDetailsFactory.CreateProblemDetails(context, @@ -161,10 +156,7 @@ public static IServiceCollection AddAndConfigureProblemDetails(this IServiceColl options.Map((context, exception) => exception.IsOrHasInner(), mapping: (context, exception) => { - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(name: $"{nameof(AMO.AsClientException)}::{nameof(MsalException)}", exception); - - context.RequestServices.GetRequiredService().TrackException(exception); + ReportMappedException(context, exception); var msalException = exception.Find(); BravoUnexpectedException.ThrowIfNull(msalException); var problemDetailsFactory = context.RequestServices.GetRequiredService(); @@ -178,10 +170,7 @@ public static IServiceCollection AddAndConfigureProblemDetails(this IServiceColl options.Map((context, exception) => { - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(name: nameof(AMO.ConnectionException), exception); - - context.RequestServices.GetRequiredService().TrackException(exception); + ReportMappedException(context, exception); var problemDetailsFactory = context.RequestServices.GetRequiredService(); var problemDetails = problemDetailsFactory.CreateProblemDetails(context, @@ -194,10 +183,7 @@ public static IServiceCollection AddAndConfigureProblemDetails(this IServiceColl options.Map((context, exception) => { - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(name: nameof(OperationCanceledException), exception); - - context.RequestServices.GetRequiredService().TrackException(exception); + ReportMappedException(context, exception); var problemDetailsFactory = context.RequestServices.GetRequiredService(); var problemDetails = problemDetailsFactory.CreateProblemDetails(context, @@ -212,10 +198,7 @@ public static IServiceCollection AddAndConfigureProblemDetails(this IServiceColl // This can result in a misleading message like a AMO.ConnectionException reported as a SocketException (NetworkError instead of AnalysisServicesConnectionFailed) options.Map(predicate: (context, exception) => exception.IsOrHasInner(), mapping: (context, exception) => { - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(name: $"{nameof(Exception)}::{nameof(SocketException)}", exception); - - context.RequestServices.GetRequiredService().TrackException(exception); + ReportMappedException(context, exception); var socketException = exception.Find(); BravoUnexpectedException.ThrowIfNull(socketException); var problemDetailsFactory = context.RequestServices.GetRequiredService(); @@ -230,8 +213,8 @@ public static IServiceCollection AddAndConfigureProblemDetails(this IServiceColl // Because exceptions are handled polymorphically, this will act as a "catch all" mapping, which is why it's added last options.Map(mapping: (context, exception) => { - AppEnvironment.AddDiagnostics(name: "UnhandledException", exception); - + // No log here: this mapping returns 500, and the problem details middleware logs every 500 response at Error, + // so a log here would record the exception twice. The 400 mappings above log because the middleware does not. context.RequestServices.GetRequiredService().TrackException(exception); return StatusCodeProblemDetails.Create(StatusCodes.Status500InternalServerError); @@ -258,4 +241,16 @@ public static IServiceCollection AddAndConfigureSwaggerGen(this IServiceCollecti return services; } + + private static ILogger GetLogger(HttpContext context) + { + var loggerFactory = context.RequestServices.GetRequiredService(); + return loggerFactory.CreateLogger(typeof(HostingExtensions)); + } + + internal static void ReportMappedException(HttpContext context, Exception exception) + { + LogExceptionMapped(GetLogger(context), exception); + context.RequestServices.GetRequiredService().TrackException(exception); + } } diff --git a/src/Infrastructure/Helpers/CommonHelper.Log.cs b/src/Infrastructure/Helpers/CommonHelper.Log.cs new file mode 100644 index 00000000..dcb78f59 --- /dev/null +++ b/src/Infrastructure/Helpers/CommonHelper.Log.cs @@ -0,0 +1,9 @@ +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.Helpers; + +internal static partial class CommonHelper +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "Update feed received: {Feed}")] + private static partial void LogUpdateFeedReceived(ILogger logger, string feed); +} diff --git a/src/Infrastructure/Helpers/CommonHelper.cs b/src/Infrastructure/Helpers/CommonHelper.cs index 53723c1d..00391b4c 100644 --- a/src/Infrastructure/Helpers/CommonHelper.cs +++ b/src/Infrastructure/Helpers/CommonHelper.cs @@ -5,6 +5,7 @@ using System.Threading; using System.Threading.Tasks; using System.Windows.Forms; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Configuration.Settings; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Windows.Interop; @@ -12,7 +13,7 @@ namespace Sqlbi.Bravo.Infrastructure.Helpers; -internal static class CommonHelper +internal static partial class CommonHelper { public static string? ChangeUriScheme(string? uriString, string scheme, bool ignorePort = false) { @@ -90,7 +91,7 @@ public static string NormalizeUriString(string uriString) return directoryName; } - public static async Task CheckForUpdateAsync(UpdateChannelType updateChannel, CancellationToken cancellationToken) + public static async Task CheckForUpdateAsync(UpdateChannelType updateChannel, ILogger logger, CancellationToken cancellationToken) { var channelPath = updateChannel switch { @@ -102,8 +103,7 @@ public static async Task CheckForUpdateAsync(UpdateChannelType upda using var httpClient = new HttpClient(); var requestUri = $"https://bravorelease.blob.core.windows.net/{channelPath}/currentversion.json?nocache={DateTimeOffset.Now.ToUnixTimeSeconds()}"; var json = await httpClient.GetStringAsync(requestUri, cancellationToken).ConfigureAwait(false); - - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CommonHelper)}.{nameof(CheckForUpdateAsync)}", content: json); + LogUpdateFeedReceived(logger, json); using var document = JsonDocument.Parse(json); var rootElement = document.RootElement; diff --git a/src/Infrastructure/Helpers/TokenCacheHelper.Log.cs b/src/Infrastructure/Helpers/TokenCacheHelper.Log.cs new file mode 100644 index 00000000..a2971df2 --- /dev/null +++ b/src/Infrastructure/Helpers/TokenCacheHelper.Log.cs @@ -0,0 +1,10 @@ +using System; +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.Helpers; + +internal static partial class TokenCacheHelper +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Warning, Message = "The token cache could not be decrypted and is deleted: the user signs in again.")] + private static partial void LogTokenCacheUnreadable(ILogger logger, Exception exception); +} diff --git a/src/Infrastructure/Helpers/TokenCacheHelper.cs b/src/Infrastructure/Helpers/TokenCacheHelper.cs index 68c69f08..7dd2d27b 100644 --- a/src/Infrastructure/Helpers/TokenCacheHelper.cs +++ b/src/Infrastructure/Helpers/TokenCacheHelper.cs @@ -1,17 +1,17 @@ using System; using System.IO; using System.Security.Cryptography; +using Microsoft.Extensions.Logging; using Microsoft.Identity.Client; using Sqlbi.Bravo.Infrastructure.Security; -using Sqlbi.Bravo.Models; namespace Sqlbi.Bravo.Infrastructure.Helpers; -internal static class TokenCacheHelper +internal static partial class TokenCacheHelper { private static readonly object _tokenCacheLock = new(); - private static void BeforeAccessCallback(TokenCacheNotificationArgs args) + private static void BeforeAccessCallback(TokenCacheNotificationArgs args, ILogger logger) { lock (_tokenCacheLock) { @@ -28,7 +28,7 @@ private static void BeforeAccessCallback(TokenCacheNotificationArgs args) } catch (CryptographicException ex) { - AppEnvironment.AddDiagnostics(name: $"{nameof(TokenCacheHelper)}.{nameof(BeforeAccessCallback)}", ex, DiagnosticMessageSeverity.Warning); + LogTokenCacheUnreadable(logger, ex); // Delete the file in order to force a new authentication File.Delete(AppEnvironment.MsalTokenCacheFilePath); @@ -58,12 +58,14 @@ private static void AfterAccessCallback(TokenCacheNotificationArgs args) /// Registers a token cache to synchronize with the persistent storage. /// /// The application token cache, typically referenced as + /// Records a cache file that cannot be decrypted. /// Call to have the given token cache stop syncronizing. - public static void RegisterCache(ITokenCache tokenCache) + public static void RegisterCache(ITokenCache tokenCache, ILogger logger) { ArgumentNullException.ThrowIfNull(tokenCache); + ArgumentNullException.ThrowIfNull(logger); - tokenCache.SetBeforeAccess(BeforeAccessCallback); + tokenCache.SetBeforeAccess((args) => BeforeAccessCallback(args, logger)); tokenCache.SetAfterAccess(AfterAccessCallback); } diff --git a/src/Infrastructure/Messages/AppInstanceStartupMessage.cs b/src/Infrastructure/Messages/AppInstanceStartupMessage.cs index 8d2c1316..d7f9c7bc 100644 --- a/src/Infrastructure/Messages/AppInstanceStartupMessage.cs +++ b/src/Infrastructure/Messages/AppInstanceStartupMessage.cs @@ -113,9 +113,6 @@ public static JsonElement ToJsonElement(this AppInstanceStartupMessage startupMe webMessageString = webMessage.AsString; } - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(AppInstanceStartupMessage)}.{nameof(ToWebMessageString)}", content: webMessageString); - return webMessageString; } } diff --git a/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationClient.cs b/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationClient.cs index 3229bb8a..9e2f777c 100644 --- a/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationClient.cs +++ b/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationClient.cs @@ -4,6 +4,7 @@ using System.Linq; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Microsoft.Identity.Client; using Microsoft.Identity.Client.Desktop; using Sqlbi.Bravo.Infrastructure.Configuration; @@ -24,7 +25,7 @@ public interface ICloudAuthenticationClient /// /// Handles authentication with Microsoft Entra ID (Azure AD) using MSAL.NET, including token acquisition and cache management. /// -internal sealed class CloudAuthenticationClient(IPolicyService policyService) : ICloudAuthenticationClient +internal sealed class CloudAuthenticationClient(IPolicyService policyService, ILogger logger) : ICloudAuthenticationClient { private const string SystemBrowserRedirectUri = "http://localhost"; @@ -34,6 +35,7 @@ internal sealed class CloudAuthenticationClient(IPolicyService policyService) : new Dictionary { ["msafed"] = ("0", false) }); private readonly IPolicyService _policyService = policyService; + private readonly ILogger _logger = logger; public async Task AcquireTokenAsync( CloudEnvironment environment, string email, CancellationToken cancellationToken) @@ -144,7 +146,7 @@ private IPublicClientApplication CreatePublicClient(CloudEnvironment environment var client = builder.Build(); - TokenCacheHelper.RegisterCache(client.UserTokenCache); + TokenCacheHelper.RegisterCache(client.UserTokenCache, _logger); return client; } diff --git a/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationService.Log.cs b/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationService.Log.cs new file mode 100644 index 00000000..68f5b4ad --- /dev/null +++ b/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationService.Log.cs @@ -0,0 +1,9 @@ +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.PowerBI.Cloud.Authentication; + +internal partial class CloudAuthenticationService +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "Signing in to the Power BI environment: {Environment}")] + private partial void LogSigningIn(string environment); +} diff --git a/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationService.cs b/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationService.cs index 20750a3b..1254d17b 100644 --- a/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationService.cs +++ b/src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationService.cs @@ -2,6 +2,7 @@ using System.Text.Json; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.PowerBI.Cloud.Configuration; using Sqlbi.Bravo.Models; @@ -19,12 +20,14 @@ public interface ICloudAuthenticationService /// /// Orchestrates PBI Cloud sign-in/out and holds session state, delegating all MSAL work to . /// -internal class CloudAuthenticationService( +internal partial class CloudAuthenticationService( ICloudAuthenticationClient cloudAuthenticationClient, - ICloudConfigurationService cloudConfigurationService) : ICloudAuthenticationService, IDisposable + ICloudConfigurationService cloudConfigurationService, + ILogger logger) : ICloudAuthenticationService, IDisposable { private readonly ICloudAuthenticationClient _cloudAuthenticationClient = cloudAuthenticationClient; private readonly ICloudConfigurationService _cloudConfigurationService = cloudConfigurationService; + private readonly ILogger _logger = logger; private readonly SemaphoreSlim _authenticationSemaphore = new(1, 1); private AuthenticatedSession? _currentSession; @@ -34,8 +37,10 @@ public async Task SignInAsync(string email, CloudEnvironme await _authenticationSemaphore.WaitAsync(cancellationToken); try { - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CloudAuthenticationService)}.{nameof(SignInAsync)}", JsonSerializer.Serialize(environment)); + if (_logger.IsEnabled(LogLevel.Information)) + { + LogSigningIn(JsonSerializer.Serialize(environment)); + } var authenticationResult = await _cloudAuthenticationClient.AcquireTokenAsync(environment, email, cancellationToken); var clusterUri = await _cloudConfigurationService.ResolveTenantClusterUriAsync(environment, authenticationResult.AccessToken, cancellationToken); diff --git a/src/Infrastructure/PowerBI/Cloud/CloudApiClient.Log.cs b/src/Infrastructure/PowerBI/Cloud/CloudApiClient.Log.cs new file mode 100644 index 00000000..f26d473b --- /dev/null +++ b/src/Infrastructure/PowerBI/Cloud/CloudApiClient.Log.cs @@ -0,0 +1,21 @@ +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.PowerBI.Cloud; + +internal partial class CloudApiClient +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "Workspaces received from the Power BI service: {Response}")] + private partial void LogWorkspacesReceived(string response); + + [LoggerMessage(EventId = 2, Level = LogLevel.Information, Message = "Shared models received from the Power BI service: {Response}")] + private partial void LogSharedModelsReceived(string response); + + [LoggerMessage(EventId = 3, Level = LogLevel.Information, Message = "Workspaces read from the response: {Workspaces}")] + private partial void LogWorkspacesRead(string workspaces); + + [LoggerMessage(EventId = 4, Level = LogLevel.Information, Message = "Shared models read from the response: {SharedModels}")] + private partial void LogSharedModelsRead(string sharedModels); + + [LoggerMessage(EventId = 5, Level = LogLevel.Information, Message = "Datasets joined from workspaces and shared models: {Datasets}")] + private partial void LogDatasetsJoined(string datasets); +} diff --git a/src/Infrastructure/PowerBI/Cloud/CloudApiClient.cs b/src/Infrastructure/PowerBI/Cloud/CloudApiClient.cs index 83b3437b..42858a66 100644 --- a/src/Infrastructure/PowerBI/Cloud/CloudApiClient.cs +++ b/src/Infrastructure/PowerBI/Cloud/CloudApiClient.cs @@ -10,6 +10,7 @@ using System.Text.Json; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.PowerBI.Cloud.Authentication; using Sqlbi.Bravo.Infrastructure.PowerBI.Cloud.Contracts; @@ -24,9 +25,10 @@ public interface ICloudApiClient Task> GetDatasetsAsync(AuthenticatedSession session, CancellationToken cancellationToken); } -internal class CloudApiClient : ICloudApiClient +internal partial class CloudApiClient : ICloudApiClient { private readonly HttpClient _httpClient; + private readonly ILogger _logger; private readonly JsonSerializerOptions _jsonOptions = new(JsonSerializerDefaults.Web) { PropertyNameCaseInsensitive = false, // required by SharedDatasetModel LastRefreshTime/lastRefreshTime properties @@ -38,9 +40,10 @@ internal class CloudApiClient : ICloudApiClient public const string ASAzureProtocolScheme = "asazure"; //public const string ASAzureLinkProtocolScheme = "link"; - public CloudApiClient(IHttpClientFactory httpClientFactory) + public CloudApiClient(IHttpClientFactory httpClientFactory, ILogger logger) { _httpClient = httpClientFactory.CreateClient(ServiceCollectionExtensions.PowerBIApiHttpClientName); + _logger = logger; } public async Task GetUserPhotoAsync(AuthenticatedSession session, CancellationToken cancellationToken) @@ -98,16 +101,18 @@ public async Task> GetDatasetsAsync(AuthenticatedSe var cloudWorkspaces = await GetCloudWorkspacesAsync(session, cancellationToken); var cloudSharedModels = await GetCloudSharedModelsAsync(session, cancellationToken); - if (AppEnvironment.IsDiagnosticLevelVerbose) + if (_logger.IsEnabled(LogLevel.Information)) { - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CloudApiClient)}.{nameof(GetDatasetsAsync)}.{nameof(cloudWorkspaces)}", content: JsonSerializer.Serialize(cloudWorkspaces)); - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CloudApiClient)}.{nameof(GetDatasetsAsync)}.{nameof(cloudSharedModels)}", content: JsonSerializer.Serialize(cloudSharedModels)); + LogWorkspacesRead(JsonSerializer.Serialize(cloudWorkspaces)); + LogSharedModelsRead(JsonSerializer.Serialize(cloudSharedModels)); } var datasets = cloudWorkspaces.Join(cloudSharedModels, (w) => w.ObjectId?.ToLowerInvariant(), (d) => d.ObjectId?.ToLowerInvariant(), (w, d) => PBICloudDataset.CreateFrom(session.Environment, w, d)).ToArray(); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CloudApiClient)}.{nameof(GetDatasetsAsync)}", content: JsonSerializer.Serialize(datasets)); + if (_logger.IsEnabled(LogLevel.Information)) + { + LogDatasetsJoined(JsonSerializer.Serialize(datasets)); + } return datasets; } @@ -126,8 +131,7 @@ private async Task> GetCloudWorkspacesAsync(Authenti var json = await httpResponse.Content.ReadAsStringAsync(cancellationToken); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CloudApiClient)}.{nameof(GetCloudWorkspacesAsync)}", json); + LogWorkspacesReceived(json); return JsonSerializer.Deserialize(json, _jsonOptions) ?? []; } @@ -146,8 +150,7 @@ private async Task> GetCloudSharedModelsAsync(Auth var json = await httpResponse.Content.ReadAsStringAsync(cancellationToken); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CloudApiClient)}.{nameof(GetCloudSharedModelsAsync)}", json); + LogSharedModelsReceived(json); return JsonSerializer.Deserialize(json, _jsonOptions) ?? []; } diff --git a/src/Infrastructure/PowerBI/Cloud/Configuration/CloudConfigurationService.Log.cs b/src/Infrastructure/PowerBI/Cloud/Configuration/CloudConfigurationService.Log.cs new file mode 100644 index 00000000..113cbbb0 --- /dev/null +++ b/src/Infrastructure/PowerBI/Cloud/Configuration/CloudConfigurationService.Log.cs @@ -0,0 +1,15 @@ +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.PowerBI.Cloud.Configuration; + +internal sealed partial class CloudConfigurationService +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "Environment discovery {ApiVersion} response received: {Response}")] + private partial void LogEnvironmentsReceived(string apiVersion, string response); + + [LoggerMessage(EventId = 2, Level = LogLevel.Information, Message = "Tenant cluster response received: {Response}")] + private partial void LogTenantClusterReceived(string response); + + [LoggerMessage(EventId = 3, Level = LogLevel.Information, Message = "Power BI environments discovered for the account: {Environments}")] + private partial void LogEnvironmentsDiscovered(string environments); +} diff --git a/src/Infrastructure/PowerBI/Cloud/Configuration/CloudConfigurationService.cs b/src/Infrastructure/PowerBI/Cloud/Configuration/CloudConfigurationService.cs index 2002d4df..d35e2d6c 100644 --- a/src/Infrastructure/PowerBI/Cloud/Configuration/CloudConfigurationService.cs +++ b/src/Infrastructure/PowerBI/Cloud/Configuration/CloudConfigurationService.cs @@ -6,13 +6,14 @@ using System.Net.Http.Headers; using System.Net.Mime; using System.Text; +using System.Text.Json; using System.Threading; using System.Threading.Tasks; using System.Web; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.PowerBI.Cloud.Contracts; using Sqlbi.Bravo.Infrastructure.PowerBI.Cloud.Serialization; -using Sqlbi.Bravo.Models; namespace Sqlbi.Bravo.Infrastructure.PowerBI.Cloud.Configuration; @@ -23,20 +24,25 @@ internal interface ICloudConfigurationService Task ResolveTenantClusterUriAsync(CloudEnvironment environment, string accessToken, CancellationToken cancellationToken); } -internal sealed class CloudConfigurationService : ICloudConfigurationService +internal sealed partial class CloudConfigurationService : ICloudConfigurationService { // The Global Cloud is the default discovery base URI for Power BI service discovery. private static readonly Uri s_defaultDiscoveryBaseUri = new("https://api.powerbi.com", UriKind.Absolute); private readonly HttpClient _httpClient; private readonly Uri _discoveryBaseUri; + private readonly ILogger _logger; - public CloudConfigurationService(IHttpClientFactory httpClientFactory, ILocalConfigurationReader localConfigurationReader) + public CloudConfigurationService( + IHttpClientFactory httpClientFactory, + ILocalConfigurationReader localConfigurationReader, + ILogger logger) { _httpClient = httpClientFactory.CreateClient(ServiceCollectionExtensions.PowerBIApiHttpClientName); _discoveryBaseUri = localConfigurationReader.GetPowerBIServiceDiscoveryBaseUri() ?? s_defaultDiscoveryBaseUri; + _logger = logger; } public async Task> DiscoverEnvironmentsAsync(string email, CancellationToken cancellationToken) @@ -47,9 +53,16 @@ public async Task> DiscoverEnvironmentsAsync(str var environments = response?.Environments ?? []; - return [.. environments + CloudEnvironment[] discovered = [.. environments .Where((e) => !e.IsMicrosoftInternalCloud()) // Filter out Microsoft internal environments .Select(CloudEnvironment.FromContract)]; + + if (_logger.IsEnabled(LogLevel.Information)) + { + LogEnvironmentsDiscovered(JsonSerializer.Serialize(discovered)); + } + + return discovered; } public async Task ResolveTenantClusterUriAsync(CloudEnvironment environment, string accessToken, CancellationToken cancellationToken) @@ -66,8 +79,7 @@ public async Task ResolveTenantClusterUriAsync(CloudEnvironment environm var json = await httpResponse.Content.ReadAsStringAsync(cancellationToken); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CloudConfigurationService)}.{nameof(ResolveTenantClusterUriAsync)}", json); + LogTenantClusterReceived(json); var tenantCluster = CloudContractJsonSerializer.Deserialize(json); return tenantCluster.FixedClusterUri; @@ -85,8 +97,7 @@ public async Task ResolveTenantClusterUriAsync(CloudEnvironment environm { var json = await httpResponse.Content.ReadAsStringAsync(cancellationToken); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(CloudConfigurationService)}.{nameof(DiscoverEnvironmentsAsync)}()", content: json); + LogEnvironmentsReceived(apiVersion, json); return CloudContractJsonSerializer.Deserialize(json); } diff --git a/src/Infrastructure/Services/ConnectionWrapper.cs b/src/Infrastructure/Services/ConnectionWrapper.cs index f208afba..65e293e0 100644 --- a/src/Infrastructure/Services/ConnectionWrapper.cs +++ b/src/Infrastructure/Services/ConnectionWrapper.cs @@ -1,6 +1,6 @@ using System; -using System.Text.Json.Nodes; using Microsoft.AnalysisServices.AdomdClient; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; using Sqlbi.Bravo.Models; @@ -8,11 +8,11 @@ namespace Sqlbi.Bravo.Infrastructure.Services; -internal class TabularConnectionWrapper : IDisposable +internal partial class TabularConnectionWrapper : IDisposable { private readonly string _connectionString; - private TabularConnectionWrapper(string connectionString, string databaseIdOrName, bool findById) + private TabularConnectionWrapper(string connectionString, string databaseIdOrName, bool findById, ILogger logger) { _connectionString = connectionString; @@ -22,16 +22,10 @@ private TabularConnectionWrapper(string connectionString, string databaseIdOrNam if (Database is null) { - if (AppEnvironment.IsDiagnosticLevelVerbose) + if (logger.IsEnabled(LogLevel.Information)) { var properties = Server.SerializeDiagnosticProperties(); - var content = new JsonObject - { - { nameof(databaseIdOrName), databaseIdOrName }, - { nameof(findById), findById }, - { nameof(properties), properties } - }; - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(TabularConnectionWrapper)}.ctor", content.ToJsonString()); + LogDatabaseNotFound(logger, databaseIdOrName, findById, properties.ToJsonString()); } throw new BravoException(BravoProblem.TOMDatabaseDatabaseNotFound, databaseIdOrName); @@ -64,22 +58,22 @@ public void Dispose() Server?.Dispose(); } - public static TabularConnectionWrapper ConnectTo(PBICloudDataset dataset, string accessToken) + public static TabularConnectionWrapper ConnectTo(PBICloudDataset dataset, string accessToken, ILogger logger) { BravoUnexpectedException.ThrowIfNull(dataset.DatabaseName); var connectionString = ConnectionStringHelper.BuildFor(dataset, accessToken); - var connection = new TabularConnectionWrapper(connectionString, dataset.DatabaseName, findById: true); + var connection = new TabularConnectionWrapper(connectionString, dataset.DatabaseName, findById: true, logger); return connection; } - public static TabularConnectionWrapper ConnectTo(PBIDesktopReport report) + public static TabularConnectionWrapper ConnectTo(PBIDesktopReport report, ILogger logger) { BravoUnexpectedException.ThrowIfNull(report.DatabaseName); var connectionString = ConnectionStringHelper.BuildFor(report); - var connection = new TabularConnectionWrapper(connectionString, report.DatabaseName, findById: false); + var connection = new TabularConnectionWrapper(connectionString, report.DatabaseName, findById: false, logger); return connection; } diff --git a/src/Infrastructure/Services/DaxTemplate/DaxTemplateManager.cs b/src/Infrastructure/Services/DaxTemplate/DaxTemplateManager.cs index f7c1c5fb..22444ad1 100644 --- a/src/Infrastructure/Services/DaxTemplate/DaxTemplateManager.cs +++ b/src/Infrastructure/Services/DaxTemplate/DaxTemplateManager.cs @@ -5,6 +5,7 @@ using System.Threading; using Dax.Template; using Dax.Template.Model; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Policies; using Sqlbi.Bravo.Models.ManageDates; @@ -32,10 +33,12 @@ internal class DaxTemplateManager private readonly object _cacheSyncLock = new(); private readonly IPolicyService _policyService; + private readonly ILogger _logger; - public DaxTemplateManager(IPolicyService policyService) + public DaxTemplateManager(IPolicyService policyService, ILogger logger) { _policyService = policyService; + _logger = logger; InitializeCache(); } @@ -57,7 +60,7 @@ public IEnumerable GetPackages() public ModelChanges GetPreviewChanges(DateConfiguration configuration, int previewRows, TabularConnectionWrapper connection, CancellationToken cancellationToken) { - var package = configuration.LoadPackage(); + var package = configuration.LoadPackage(_logger); return GetPreviewChanges(package, previewRows, connection, cancellationToken); } @@ -86,7 +89,7 @@ public ModelChanges GetPreviewChanges(Package package, int previewRows, TabularC public void ApplyConfiguration(DateConfiguration configuration, TabularConnectionWrapper connection, CancellationToken cancellationToken) { - var package = configuration.LoadPackage(); + var package = configuration.LoadPackage(_logger); var engine = new Engine(package); engine.ApplyTemplates(connection.Model, cancellationToken); diff --git a/src/Infrastructure/Services/PowerBI/PBIDesktopService.cs b/src/Infrastructure/Services/PowerBI/PBIDesktopService.cs index 2a6612a6..22ff2787 100644 --- a/src/Infrastructure/Services/PowerBI/PBIDesktopService.cs +++ b/src/Infrastructure/Services/PowerBI/PBIDesktopService.cs @@ -3,6 +3,7 @@ using System.Collections.Generic; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; using Sqlbi.Bravo.Infrastructure.Windows; @@ -15,8 +16,10 @@ public interface IPBIDesktopService IEnumerable GetReports(CancellationToken cancellationToken); } -internal class PBIDesktopService : IPBIDesktopService +internal class PBIDesktopService(ILogger logger) : IPBIDesktopService { + private readonly ILogger _logger = logger; + public IEnumerable GetReports(CancellationToken cancellationToken) { var processes = ProcessHelper.GetProcessesByName(PowerBIDesktop.ProcessName); @@ -27,7 +30,7 @@ public IEnumerable GetReports(CancellationToken cancellationTo var parallelOptions = new ParallelOptions { CancellationToken = cancellationToken }; var parallelLoop = Parallel.ForEach(processes, parallelOptions, (process) => { - var report = PBIDesktopReport.CreateFrom(process, processTree); + var report = PBIDesktopReport.CreateFrom(process, _logger, processTree); reports.Add(report); }); diff --git a/src/Infrastructure/Services/TabularConnectionWrapper.Log.cs b/src/Infrastructure/Services/TabularConnectionWrapper.Log.cs new file mode 100644 index 00000000..e9647964 --- /dev/null +++ b/src/Infrastructure/Services/TabularConnectionWrapper.Log.cs @@ -0,0 +1,9 @@ +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Infrastructure.Services; + +internal partial class TabularConnectionWrapper +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "Database {DatabaseIdOrName} not found (by ID: {FindById}) among the databases of the server: {ServerDatabases}")] + private static partial void LogDatabaseNotFound(ILogger logger, string databaseIdOrName, bool findById, string serverDatabases); +} diff --git a/src/Infrastructure/Telemetry/DefaultTelemetryProcessor.cs b/src/Infrastructure/Telemetry/DefaultTelemetryProcessor.cs index 8910e7c6..c4782855 100644 --- a/src/Infrastructure/Telemetry/DefaultTelemetryProcessor.cs +++ b/src/Infrastructure/Telemetry/DefaultTelemetryProcessor.cs @@ -1,5 +1,4 @@ -using System.Text.RegularExpressions; -using Microsoft.ApplicationInsights.Channel; +using Microsoft.ApplicationInsights.Channel; using Microsoft.ApplicationInsights.DataContracts; using Microsoft.ApplicationInsights.Extensibility; @@ -7,13 +6,6 @@ namespace Sqlbi.Bravo.Infrastructure.Telemetry; internal sealed class DefaultTelemetryProcessor : ITelemetryProcessor { - /// - /// Sensitive tags used in error messages: , , , , ]]> - /// - private static readonly Regex s_sensitiveTagsRegex = new( - @"<(pii|oii|euii|eupi|conn)>(.*?)", - RegexOptions.Compiled | RegexOptions.IgnoreCase | RegexOptions.Singleline); - private readonly ITelemetryProcessor _next; public DefaultTelemetryProcessor(ITelemetryProcessor next) @@ -35,18 +27,10 @@ private static void RedactExceptionTelemetry(ExceptionTelemetry telemetry) { // Redact Message first since it overwrites ExceptionDetailsInfoList[0].Message if (!string.IsNullOrEmpty(telemetry.Message)) - telemetry.Message = Redact(telemetry.Message); + telemetry.Message = SensitiveTags.Redact(telemetry.Message); // Redact the serialized exception details — these are what AI actually transmits foreach (var info in telemetry.ExceptionDetailsInfoList) - info.Message = Redact(info.Message); - } - - private static string Redact(string? input) - { - if (string.IsNullOrEmpty(input)) - return input ?? string.Empty; - - return s_sensitiveTagsRegex.Replace(input, "<$1>[REDACTED]"); + info.Message = SensitiveTags.Redact(info.Message); } } diff --git a/src/Infrastructure/Telemetry/SensitiveTags.cs b/src/Infrastructure/Telemetry/SensitiveTags.cs new file mode 100644 index 00000000..9d7525bc --- /dev/null +++ b/src/Infrastructure/Telemetry/SensitiveTags.cs @@ -0,0 +1,39 @@ +using System.Text.RegularExpressions; + +namespace Sqlbi.Bravo.Infrastructure.Telemetry; + +/// +/// Redacts the text that Analysis Services and other libraries mark as sensitive in error messages, with the tags +/// , , , , ]]>. +/// +/// +/// The same tags are redacted by Utils.Obj.anonymize in src/Scripts/helpers/utils.ts when the diagnostics +/// pane copies a message; a test checks that both lists match. +/// +internal static partial class SensitiveTags +{ + internal const string TagNames = "pii|oii|euii|eupi|conn"; + + private const string RedactedText = "[REDACTED]"; + + public static string Redact(string? input) + { + if (input is null) + { + return string.Empty; + } + + try + { + return TagRegex().Replace(input, $"<$1>{RedactedText}"); + } + catch (RegexMatchTimeoutException) + { + // A text too costly to scan, such as one with many unclosed tags, is withheld rather than let through. + return RedactedText; + } + } + + [GeneratedRegex(@"<(" + TagNames + @")>(.*?)", RegexOptions.IgnoreCase | RegexOptions.Singleline, matchTimeoutMilliseconds: 1000)] + private static partial Regex TagRegex(); +} diff --git a/src/Models/DiagnosticMessage.cs b/src/Models/DiagnosticMessage.cs deleted file mode 100644 index 5e5fe9e8..00000000 --- a/src/Models/DiagnosticMessage.cs +++ /dev/null @@ -1,52 +0,0 @@ -using System; -using System.Text.Json.Serialization; - -namespace Sqlbi.Bravo.Models; - -public class DiagnosticMessage -{ - [JsonPropertyName("type")] - public DiagnosticMessageType Type { get; set; } = DiagnosticMessageType.Text; - - [JsonPropertyName("severity")] - public DiagnosticMessageSeverity Severity { get; set; } = DiagnosticMessageSeverity.None; - - [JsonPropertyName("name")] - public string? Name { get; set; } - - [JsonPropertyName("content")] - public string? Content { get; set; } - - [JsonPropertyName("timestamp")] - public DateTime Timestamp { get; set; } = DateTime.UtcNow; - - [JsonIgnore] - public DateTime? ReadTimestamp { get; set; } - - internal static DiagnosticMessage Create(DiagnosticMessageType type, DiagnosticMessageSeverity severity, string name, string content) - { - var message = new DiagnosticMessage - { - Type = type, - Severity = severity, - Name = $"[HOST] {name}", - Content = content, - ReadTimestamp = null - }; - - return message; - } -} - -public enum DiagnosticMessageType -{ - Text = 0, - Json = 1, -} - -public enum DiagnosticMessageSeverity -{ - None = 0, - Warning = 1, - Error = 2, -} diff --git a/src/Models/ManageDates/DateConfiguration.cs b/src/Models/ManageDates/DateConfiguration.cs index b4f2935f..931ab5a6 100644 --- a/src/Models/ManageDates/DateConfiguration.cs +++ b/src/Models/ManageDates/DateConfiguration.cs @@ -9,6 +9,7 @@ using Dax.Template.Exceptions; using Dax.Template.Interfaces; using Dax.Template.Tables; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure; using Sqlbi.Bravo.Infrastructure.Configuration; using Sqlbi.Bravo.Infrastructure.Extensions; @@ -427,9 +428,9 @@ public static DateConfiguration CreateFrom(Dax.Template.Package package) } } -internal static class DateConfigurationExtensions +internal static partial class DateConfigurationExtensions { - public static Dax.Template.Package LoadPackage(this DateConfiguration configuration, bool configure = true) + public static Dax.Template.Package LoadPackage(this DateConfiguration configuration, ILogger logger, bool configure = true) { BravoUnexpectedException.ThrowIfNull(configuration.TemplateUri); @@ -455,8 +456,7 @@ public static Dax.Template.Package LoadPackage(this DateConfiguration configurat { var templatesOptionFound = UserPreferences.Current.CustomOptions.Value.TryGetProperty("templates", out var templatesOption); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Json, name: $"{nameof(DateConfigurationExtensions)}.{nameof(LoadPackage)}.CustomOptions.Templates[{templatesOption.ValueKind}]", content: templatesOption.ToString()); + LogCustomTemplatesOptionRead(logger, templatesOption.ValueKind, templatesOption); if (templatesOptionFound) { diff --git a/src/Models/ManageDates/DateConfigurationExtensions.Log.cs b/src/Models/ManageDates/DateConfigurationExtensions.Log.cs new file mode 100644 index 00000000..326798dd --- /dev/null +++ b/src/Models/ManageDates/DateConfigurationExtensions.Log.cs @@ -0,0 +1,10 @@ +using System.Text.Json; +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Models.ManageDates; + +internal static partial class DateConfigurationExtensions +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "Custom templates option read from the user settings ({ValueKind}): {Templates}")] + private static partial void LogCustomTemplatesOptionRead(ILogger logger, JsonValueKind valueKind, JsonElement templates); +} diff --git a/src/Models/PBIDesktopReport.Log.cs b/src/Models/PBIDesktopReport.Log.cs new file mode 100644 index 00000000..87dbb72e --- /dev/null +++ b/src/Models/PBIDesktopReport.Log.cs @@ -0,0 +1,10 @@ +using System; +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Models; + +public partial class PBIDesktopReport +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "The model of Power BI Desktop process {ProcessId} could not be reached to find its connection mode.")] + private static partial void LogConnectionModeUnavailable(ILogger logger, int? processId, Exception exception); +} diff --git a/src/Models/PBIDesktopReport.cs b/src/Models/PBIDesktopReport.cs index df9abbb9..aec5948b 100644 --- a/src/Models/PBIDesktopReport.cs +++ b/src/Models/PBIDesktopReport.cs @@ -5,7 +5,7 @@ using System.Net; using System.Net.NetworkInformation; using System.Text.Json.Serialization; -using Sqlbi.Bravo.Infrastructure; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; using Sqlbi.Bravo.Infrastructure.Models; @@ -17,7 +17,7 @@ namespace Sqlbi.Bravo.Models; [DebuggerDisplay("{ServerName} - {ReportName} - {ConnectionMode}")] -public class PBIDesktopReport : IDataModel +public partial class PBIDesktopReport : IDataModel { public PBIDesktopReport() { @@ -60,13 +60,13 @@ public override int GetHashCode() return HashCode.Combine(ProcessId, ServerName, DatabaseName); } - internal static PBIDesktopReport? CreateFrom(int processId, bool connectionModeEnabled = true) + internal static PBIDesktopReport? CreateFrom(int processId, ILogger logger, bool connectionModeEnabled = true) { using var process = ProcessHelper.SafeGetProcessById(processId); if (process is not null) { - var report = CreateFrom(process, processTree: null, connectionModeEnabled); + var report = CreateFrom(process, logger, processTree: null, connectionModeEnabled); return report; } @@ -74,11 +74,12 @@ public override int GetHashCode() } /// The Power BI Desktop process. + /// Records why the connection to the model failed. /// /// A snapshot shared by the reports created together; takes one when it is needed. /// /// Whether to connect to the model to find its connection mode. - internal static PBIDesktopReport CreateFrom(Process process, ProcessTree? processTree = null, bool connectionModeEnabled = true) + internal static PBIDesktopReport CreateFrom(Process process, ILogger logger, ProcessTree? processTree = null, bool connectionModeEnabled = true) { var report = new PBIDesktopReport { @@ -140,8 +141,7 @@ void GetConnectionMode(out string? serverName, out string? databaseName, out SSA } catch (Exception ex) { - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(name: $"{nameof(PBIDesktopReport)}.{nameof(CreateFrom)}.{nameof(GetConnectionMode)}", ex, DiagnosticMessageSeverity.Warning); + LogConnectionModeUnavailable(logger, report.ProcessId, ex); connectionMode = PBIDesktopReportConnectionMode.UnsupportedConnectionException; return; diff --git a/src/Scripts/controllers/host.ts b/src/Scripts/controllers/host.ts index ece65985..4e68ac07 100644 --- a/src/Scripts/controllers/host.ts +++ b/src/Scripts/controllers/host.ts @@ -82,22 +82,38 @@ export interface DatabaseUpdateResult { etag?: string } -export enum DiagnosticMessageSeverity { - None = 0, - Warning = 1, - Error = 2, +export enum HostLogLevel { + Trace = 0, + Debug = 1, + Information = 2, + Warning = 3, + Error = 4, + Critical = 5, } -export enum DiagnosticMessageType { - Text = 0, - Json = 1, +export interface DiagnosticLogException { + type: string + message: string + stackTrace?: string + details?: Dic } -export interface DiagnosticMessage { - type: DiagnosticMessageType - severity: DiagnosticMessageSeverity - name?: string - content?: string - timestamp?: string + +export interface DiagnosticLogEntry { + timestamp: string + level: HostLogLevel + category: string + eventId: number + eventName?: string + message: string + template?: string + properties?: Dic + exception?: DiagnosticLogException[] +} + +export interface DiagnosticLogPage { + entries: DiagnosticLogEntry[] + lastSequence: number + droppedCount: number } @@ -605,9 +621,9 @@ export class Host extends Dispatchable { return this.apiCall("api/NavigateTo", { address: url }); } - getDiagnostics(all = false) { - return >this.apiCall("api/GetDiagnostics", { all: all }); - } + getDiagnostics(after: number, max: number) { + return >this.apiCall("api/GetDiagnostics", { after: after, max: max }); + } getCurrentVersion(updateChannel: UpdateChannelType) { return >this.apiCall("api/GetCurrentVersion", { updateChannel: updateChannel }); diff --git a/src/Scripts/controllers/logger.ts b/src/Scripts/controllers/logger.ts index 3c0bc0af..68a314d6 100644 --- a/src/Scripts/controllers/logger.ts +++ b/src/Scripts/controllers/logger.ts @@ -11,7 +11,7 @@ import { AppError, AppErrorType } from '../model/exceptions'; import { i18n } from '../model/i18n'; import { pii } from '../model/pii'; import { strings } from '../model/strings'; -import { DiagnosticMessage, DiagnosticMessageSeverity } from './host'; +import { DiagnosticLogEntry, DiagnosticLogPage, HostLogLevel } from './host'; import { DiagnosticLevelType } from './options'; export interface LogMessage { @@ -33,9 +33,12 @@ export interface LogMessageObj { export class Logger extends Dispatchable { static MaxMessages = 50; + static HostPrefix = "[HOST]"; static CheckSeconds = 5; checkTimeout = 0; + hostCursor = 0; + checking = false; logs: Dic = {}; _enabled = false; @@ -44,6 +47,8 @@ export class Logger extends Dispatchable { } set enabled(enabled: boolean) { + if (enabled == this._enabled) return; + if (enabled) { this.checkTimeout = window.setInterval(() => { this.check(); @@ -60,24 +65,57 @@ export class Logger extends Dispatchable { this.enabled = enabled; if (enabled) - this.check(true); + this.check(); optionsController.on("diagnosticLevel.change", () => { this.enabled = (optionsController.options.diagnosticLevel !== DiagnosticLevelType.None); }); } - check(initial = false) { - if (!this.enabled) return; - if (!Logger.LevelMatch(DiagnosticLevelType.Verbose)) return; + check() { + if (!this.enabled || this.checking) return; + + // The host keeps its records, so the cursor alone decides what is new: a reload reads the newest ones again. + this.checking = true; + host.getDiagnostics(this.hostCursor, Logger.MaxMessages) + .then((page: DiagnosticLogPage) => { + if (page.droppedCount > 0) + this.log(`${ Logger.HostPrefix } ${ page.droppedCount } earlier messages are not shown`, null, DiagnosticLevelType.Basic); - host.getDiagnostics(initial) - .then((messages: DiagnosticMessage[]) => { - messages.forEach(message => { - this.log(message.name, { content: message.content }, DiagnosticLevelType.Verbose, Date.parse(message.timestamp), message.severity > DiagnosticMessageSeverity.None ? "errorMessage" : ""); - }); + page.entries.forEach(entry => this.logHostEntry(entry)); + this.hostCursor = page.lastSequence; }) - .catch(ignore=>{}); + .catch(ignore=>{}) + .finally(() => this.checking = false); + } + + logHostEntry(entry: DiagnosticLogEntry) { + const isProblem = (entry.level >= HostLogLevel.Warning || !!entry.exception); + const level = (entry.level >= HostLogLevel.Warning ? DiagnosticLevelType.Basic : DiagnosticLevelType.Verbose); + // Generic arguments are dropped first: they contain dots of their own. + const category = entry.category.replace(/<.*$/, "").split(".").pop(); + const name = `${ Logger.HostPrefix } ${ category }${ entry.eventName ? `.${ entry.eventName }` : "" }`; + + let content: Dic = { Message: entry.template ?? entry.message }; + if (entry.properties) { + for (const key in entry.properties) + content[key] = Logger.ParseJsonContainer(entry.properties[key]); + } + if (entry.exception) + content.Exception = entry.exception; + + this.log(name, { content: content }, level, Date.parse(entry.timestamp), isProblem ? "errorMessage" : ""); + } + + // Only objects and arrays are parsed: a plain value such as an identifier stays the text the host logged. + static ParseJsonContainer(value: string) { + const text = value?.trim(); + if (text && (text.startsWith("{") || text.startsWith("["))) { + try { + return JSON.parse(text); + } catch (ignore) {} + } + return value; } log(name: string, obj?: LogMessageObj, level: DiagnosticLevelType = DiagnosticLevelType.Basic, time?: number, className?: string, forceLogging = false): string { diff --git a/src/Scripts/helpers/utils.ts b/src/Scripts/helpers/utils.ts index a8de8bc4..db37c0d1 100644 --- a/src/Scripts/helpers/utils.ts +++ b/src/Scripts/helpers/utils.ts @@ -620,8 +620,9 @@ export module Utils { return prop; }; + // The same tags as SensitiveTags.cs in the host, which redacts them in telemetry; a test there checks both lists. const removePii = (value: string) => { - return value.replace(/(.|\n)+?<\/pii>/gi, anonChar + anonChar + anonChar); + return value.replace(/<(pii|oii|euii|eupi|conn)>[\s\S]*?<\/\1>/gi, anonChar + anonChar + anonChar); }; const process = (source: any) => { diff --git a/src/Services/AnalyzeModelService.cs b/src/Services/AnalyzeModelService.cs index 4212c8e3..28106a35 100644 --- a/src/Services/AnalyzeModelService.cs +++ b/src/Services/AnalyzeModelService.cs @@ -2,6 +2,7 @@ using System.IO; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; @@ -35,11 +36,13 @@ internal sealed class AnalyzeModelService : IAnalyzeModelService { private readonly ICloudApiClient _cloudApiClient; private readonly IPBIDesktopService _pbidesktopService; + private readonly ILogger _logger; - public AnalyzeModelService(ICloudApiClient cloudApiClient, IPBIDesktopService pbidesktopService) + public AnalyzeModelService(ICloudApiClient cloudApiClient, IPBIDesktopService pbidesktopService, ILogger logger) { _cloudApiClient = cloudApiClient; _pbidesktopService = pbidesktopService; + _logger = logger; } public TabularDatabase GetDatabase(Stream vpaxStream, Stream? obfuscatorDictionaryStream = null) @@ -49,7 +52,7 @@ public TabularDatabase GetDatabase(Stream vpaxStream, Stream? obfuscatorDictiona public TabularDatabase GetDatabase(PBIDesktopReport report, CancellationToken cancellationToken) { - using var connection = TabularConnectionWrapper.ConnectTo(report); + using var connection = TabularConnectionWrapper.ConnectTo(report, _logger); var database = TabularDatabase.CreateFrom(connection, cancellationToken); if (connection.Server.IsPowerBIDesktop() == false) @@ -68,7 +71,7 @@ public TabularDatabase GetDatabase(PBICloudDataset dataset, string accessToken, if (dataset.IsXmlaEndPointSupported || dataset.IsOnPremModel == true) { - using var connection = TabularConnectionWrapper.ConnectTo(dataset, accessToken); + using var connection = TabularConnectionWrapper.ConnectTo(dataset, accessToken, _logger); database = TabularDatabase.CreateFrom(connection, cancellationToken); } else @@ -101,13 +104,13 @@ public IEnumerable GetReports(CancellationToken cancellationTo public void ExportVpax(PBIDesktopReport report, ExportVpaxMode mode, string path, CancellationToken cancellationToken) { - using var connection = TabularConnectionWrapper.ConnectTo(report); + using var connection = TabularConnectionWrapper.ConnectTo(report, _logger); ExportVpaxImpl(connection, mode, path, cancellationToken); } public void ExportVpax(PBICloudDataset dataset, string accessToken, ExportVpaxMode mode, string path, CancellationToken cancellationToken) { - using var connection = TabularConnectionWrapper.ConnectTo(dataset, accessToken); + using var connection = TabularConnectionWrapper.ConnectTo(dataset, accessToken, _logger); ExportVpaxImpl(connection, mode, path, cancellationToken); } diff --git a/src/Services/ExportDataService.Log.cs b/src/Services/ExportDataService.Log.cs new file mode 100644 index 00000000..865773ff --- /dev/null +++ b/src/Services/ExportDataService.Log.cs @@ -0,0 +1,9 @@ +using Microsoft.Extensions.Logging; + +namespace Sqlbi.Bravo.Services; + +internal partial class ExportDataService +{ + [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "Exporting table {TableName} to {Format}, row batch mode: {RowBatchMode}.")] + private partial void LogTableExporting(string? tableName, string format, bool rowBatchMode); +} diff --git a/src/Services/ExportDataService.cs b/src/Services/ExportDataService.cs index cddbdb0b..db442cf7 100644 --- a/src/Services/ExportDataService.cs +++ b/src/Services/ExportDataService.cs @@ -11,6 +11,7 @@ using CsvHelper.TypeConversion; using LargeXlsx; using Microsoft.AnalysisServices.AdomdClient; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; @@ -36,7 +37,7 @@ public interface IExportDataService ExportDataJob? QueryExportJob(PBICloudDataset dataset); } -internal class ExportDataService : IExportDataService +internal partial class ExportDataService(ILogger logger) : IExportDataService { private const int BatchSize = 10_000; private const int ExcelMaxRows = 1_000_000; // Excel cannot exceed the limit of 1,048,576 rows and 16,384 columns @@ -51,6 +52,7 @@ internal class ExportDataService : IExportDataService private readonly ExportDataJobMap _datasetJobs = new(); private readonly ExportDataJobMap _reportJobs = new(); + private readonly ILogger _logger = logger; public ExportDataJob ExportDelimitedTextFile(PBIDesktopReport report, ExportDelimitedTextSettings settings, string path, CancellationToken cancellationToken) { @@ -182,7 +184,7 @@ public ExportDataJob ExportExcelFile(PBICloudDataset dataset, ExportExcelSetting return job; } - private static void ExportDelimitedTextFileImpl(ExportDataJob job, ExportDelimitedTextSettings settings, AdomdConnectionWrapper connection, CancellationToken cancellationToken) + private void ExportDelimitedTextFileImpl(ExportDataJob job, ExportDelimitedTextSettings settings, AdomdConnectionWrapper connection, CancellationToken cancellationToken) { Directory.CreateDirectory(settings.ExportPath); @@ -205,6 +207,7 @@ private static void ExportDelimitedTextFileImpl(ExportDataJob job, ExportDelimit var path = Path.Combine(settings.ExportPath, fileName); // Enable row batch mode only if TOPNSKIP is supported var rowBatchMode = connection.IsServerVersion13OrGreater && tableName.IsDirectQuery == false; + LogTableExporting(tableName.Name, "CSV", rowBatchMode); Encoding encoding = settings.UnicodeEncoding ? new UnicodeEncoding() @@ -220,9 +223,6 @@ static void Export(AdomdCommand command, ExportDataTable table, CsvWriter writer { var tableName = TabularModelHelper.GetDaxTableName(table.Name); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Text, name: $"{nameof(ExportDataService)}.{nameof(ExportDelimitedTextFileImpl)}.{nameof(Export)}", content: $"Export table {tableName} in {(rowBatchMode ? "row batch" : "full")} mode"); - if (rowBatchMode) { var batchCount = 0; @@ -305,7 +305,7 @@ static int WriteData(ExportDataTable table, CsvWriter writer, IDataReader reader } } - private static void ExportExcelFileImpl(ExportDataJob job, ExportExcelSettings settings, AdomdConnectionWrapper connection, CancellationToken cancellationToken) + private void ExportExcelFileImpl(ExportDataJob job, ExportExcelSettings settings, AdomdConnectionWrapper connection, CancellationToken cancellationToken) { var xlsxFile = new FileInfo(settings.ExportPath); @@ -326,6 +326,7 @@ private static void ExportExcelFileImpl(ExportDataJob job, ExportExcelSettings s var worksheetName = GetWorksheetName(tableName.Name, tableIndex); // Enable row batch mode only if TOPNSKIP is supported var rowBatchMode = connection.IsServerVersion13OrGreater && tableName.IsDirectQuery == false; + LogTableExporting(tableName.Name, "Excel", rowBatchMode); xlsxWriter.BeginWorksheet(worksheetName, splitRow: 1); Export(command, table, xlsxWriter, rowBatchMode, cancellationToken); @@ -392,9 +393,6 @@ static void Export(AdomdCommand command, ExportDataTable table, XlsxWriter write { var tableName = TabularModelHelper.GetDaxTableName(table.Name); - if (AppEnvironment.IsDiagnosticLevelVerbose) - AppEnvironment.AddDiagnostics(DiagnosticMessageType.Text, name: $"{nameof(ExportDataService)}.{nameof(ExportExcelFileImpl)}.{nameof(Export)}", content: $"Export table {tableName} in {(rowBatchMode ? "row batch" : "full")} mode"); - if (rowBatchMode) { var batchCount = 0; diff --git a/src/Services/FormatDaxService.cs b/src/Services/FormatDaxService.cs index bf93ddca..128794f9 100644 --- a/src/Services/FormatDaxService.cs +++ b/src/Services/FormatDaxService.cs @@ -3,6 +3,7 @@ using System.Threading.Tasks; using Dax.Formatter; using Dax.Formatter.Models; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; @@ -25,10 +26,12 @@ public interface IFormatDaxService internal class FormatDaxService : IFormatDaxService { private readonly IDaxFormatterClient _daxformatterClient; + private readonly ILogger _logger; - public FormatDaxService(IDaxFormatterClient daxformatterClient) + public FormatDaxService(IDaxFormatterClient daxformatterClient, ILogger logger) { _daxformatterClient = daxformatterClient; + _logger = logger; } public async Task> FormatAsync(IEnumerable measures, FormatDaxOptions options) @@ -78,7 +81,7 @@ public async Task> FormatAsync(IEnumerable measures) { - using var connection = TabularConnectionWrapper.ConnectTo(report); + using var connection = TabularConnectionWrapper.ConnectTo(report, _logger); var updateResult = TabularModelHelper.Update(connection.Database, measures); return updateResult; @@ -86,7 +89,7 @@ public DatabaseUpdateResult Update(PBIDesktopReport report, IEnumerable measures, string accessToken) { - using var connection = TabularConnectionWrapper.ConnectTo(dataset, accessToken); + using var connection = TabularConnectionWrapper.ConnectTo(dataset, accessToken, _logger); var updateResult = TabularModelHelper.Update(connection.Database, measures); return updateResult; diff --git a/src/Services/ManageDatesService.cs b/src/Services/ManageDatesService.cs index 24260431..0c0da75c 100644 --- a/src/Services/ManageDatesService.cs +++ b/src/Services/ManageDatesService.cs @@ -6,6 +6,7 @@ using Dax.Template.Exceptions; using Dax.Template.Model; using Microsoft.AnalysisServices.AdomdClient; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; @@ -31,10 +32,12 @@ public interface IManageDatesService internal class ManageDatesService : IManageDatesService { private readonly DaxTemplateManager _templateManager; + private readonly ILogger _logger; - public ManageDatesService(IPolicyService policyService) + public ManageDatesService(IPolicyService policyService, ILogger logger) { - _templateManager = new DaxTemplateManager(policyService); + _logger = logger; + _templateManager = new DaxTemplateManager(policyService, logger); } public IEnumerable GetConfigurations(PBIDesktopReport report, CancellationToken cancellationToken) @@ -50,7 +53,7 @@ public IEnumerable GetConfigurations(PBIDesktopReport report, } var configurations = packages.Select(DateConfiguration.CreateFrom).ToList(); - using var connection = TabularConnectionWrapper.ConnectTo(report); + using var connection = TabularConnectionWrapper.ConnectTo(report, _logger); var currentConfiguration = DateConfiguration.GetCurrentFrom(connection.Model); if (currentConfiguration is not null) @@ -73,7 +76,7 @@ public DateConfiguration ValidateConfiguration(PBIDesktopReport report, DateConf BravoUnexpectedException.ThrowIfNull(settings.Configuration); Validate(report, settings.Configuration, assertValidation: true); - using var connection = TabularConnectionWrapper.ConnectTo(report); + using var connection = TabularConnectionWrapper.ConnectTo(report, _logger); try { var modelChanges = _templateManager.GetPreviewChanges(settings.Configuration, settings.PreviewRows, connection, cancellationToken); @@ -89,7 +92,7 @@ public void ApplyConfiguration(PBIDesktopReport report, DateConfiguration config { Validate(report, configuration, assertValidation: true); - using var connection = TabularConnectionWrapper.ConnectTo(report); + using var connection = TabularConnectionWrapper.ConnectTo(report, _logger); try { _templateManager.ApplyConfiguration(configuration, connection, cancellationToken); @@ -100,11 +103,11 @@ public void ApplyConfiguration(PBIDesktopReport report, DateConfiguration config } } - private static void Validate(PBIDesktopReport report, DateConfiguration configuration, bool assertValidation) => Validate(report, new[] { configuration }, assertValidation); + private void Validate(PBIDesktopReport report, DateConfiguration configuration, bool assertValidation) => Validate(report, new[] { configuration }, assertValidation); - private static void Validate(PBIDesktopReport report, IEnumerable configurations, bool assertValidation) + private void Validate(PBIDesktopReport report, IEnumerable configurations, bool assertValidation) { - using var connection = TabularConnectionWrapper.ConnectTo(report); + using var connection = TabularConnectionWrapper.ConnectTo(report, _logger); foreach (var configuration in configurations) { diff --git a/src/Services/TemplateDevelopmentService.cs b/src/Services/TemplateDevelopmentService.cs index 03680df5..1474f5d0 100644 --- a/src/Services/TemplateDevelopmentService.cs +++ b/src/Services/TemplateDevelopmentService.cs @@ -7,6 +7,7 @@ using Dax.Template.Exceptions; using Dax.Template.Model; using Microsoft.AnalysisServices.AdomdClient; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure; using Sqlbi.Bravo.Infrastructure.Extensions; using Sqlbi.Bravo.Infrastructure.Helpers; @@ -53,12 +54,14 @@ internal class TemplateDevelopmentService : ITemplateDevelopmentService private readonly DaxTemplateManager _templateManager; private readonly IServerAddressProvider _serverAddressProvider; private readonly IPolicyService _policyService; + private readonly ILogger _logger; - public TemplateDevelopmentService(IServerAddressProvider serverAddressProvider, IPolicyService policyService) + public TemplateDevelopmentService(IServerAddressProvider serverAddressProvider, IPolicyService policyService, ILogger logger) { _serverAddressProvider = serverAddressProvider; _policyService = policyService; - _templateManager = new DaxTemplateManager(policyService); + _logger = logger; + _templateManager = new DaxTemplateManager(policyService, logger); _serializerOptions = new JsonSerializerOptions(AppEnvironment.DefaultJsonOptions) { WriteIndented = true }; } @@ -245,7 +248,7 @@ public CustomPackage CreateWorkspace(string path, string name, DateConfiguration HasWorkspace = true, HasPackage = false, }; - var package = configuration.LoadPackage(configure: false); + var package = configuration.LoadPackage(_logger, configure: false); // src\*.json files { @@ -382,7 +385,7 @@ public bool ConfigureWorkspace(string path, bool openCodeWorkspace) { BravoUnexpectedException.ThrowIfNull(settings.CustomPackagePath); - using var connection = TabularConnectionWrapper.ConnectTo(report); + using var connection = TabularConnectionWrapper.ConnectTo(report, _logger); try { var package = Dax.Template.Package.LoadFromFile(settings.CustomPackagePath); diff --git a/test/Bravo.Tests/Controllers/ApplicationControllerTests.cs b/test/Bravo.Tests/Controllers/ApplicationControllerTests.cs new file mode 100644 index 00000000..3e3912b7 --- /dev/null +++ b/test/Bravo.Tests/Controllers/ApplicationControllerTests.cs @@ -0,0 +1,51 @@ +using Bravo.Tests.Host; +using Bravo.Tests.Infrastructure.Diagnostics; +using Bravo.Tests.Infrastructure.Policies; +using Microsoft.AspNetCore.Mvc; +using Microsoft.Extensions.Logging.Abstractions; +using Sqlbi.Bravo.Controllers; +using Sqlbi.Bravo.Infrastructure.Diagnostics; +using Sqlbi.Bravo.Infrastructure.Policies; +using Xunit; + +namespace Bravo.Tests.Controllers; + +public class ApplicationControllerTests +{ + [Fact] + public void GetDiagnostics_ReturnsTheRecordsAfterTheCursor() + { + var diagnosticLog = new DiagnosticLogStore(); + diagnosticLog.Add(TestLogEntries.Create("read")); + diagnosticLog.Add(TestLogEntries.Create("new")); + var controller = CreateController(diagnosticLog); + + var result = Assert.IsType(controller.GetDiagnostics(after: 1)); + + var page = Assert.IsType(result.Value); + Assert.Equal("new", Assert.Single(page.Entries).Message); + Assert.Equal(2, page.LastSequence); + } + + [Fact] + public void GetDiagnostics_ReturnsAtMostTheRequestedNumberOfRecords() + { + var diagnosticLog = new DiagnosticLogStore(); + diagnosticLog.Add(TestLogEntries.Create("older")); + diagnosticLog.Add(TestLogEntries.Create("newer")); + var controller = CreateController(diagnosticLog); + + var result = Assert.IsType(controller.GetDiagnostics(after: 0, max: 1)); + + var page = Assert.IsType(result.Value); + Assert.Equal("newer", Assert.Single(page.Entries).Message); + Assert.Equal(1, page.DroppedCount); + } + + private static ApplicationController CreateController(DiagnosticLogStore diagnosticLog) + { + var policyService = new PolicyService(new FakePolicyReader()); + var logger = NullLogger.Instance; + return new ApplicationController(new FakeTelemetry(), policyService, new DiagnosticLevelSwitch(), diagnosticLog, logger); + } +} diff --git a/test/Bravo.Tests/Host/BootstrapContextTests.cs b/test/Bravo.Tests/Host/BootstrapContextTests.cs index 393cc41c..d9a3bdc0 100644 --- a/test/Bravo.Tests/Host/BootstrapContextTests.cs +++ b/test/Bravo.Tests/Host/BootstrapContextTests.cs @@ -21,7 +21,7 @@ public void Dispose_DisposesTheOwnedServicesOnce() { var loggerFactory = new FakeLoggerFactory(); var telemetry = new FakeTelemetry(); - var context = new BootstrapContext(loggerFactory, new PolicyService(new FakePolicyReader()), new UserSettings(), telemetry); + var context = new BootstrapContext(loggerFactory, new DiagnosticLevelSwitch(), new DiagnosticLogStore(), new PolicyService(new FakePolicyReader()), new UserSettings(), telemetry); context.Dispose(); context.Dispose(); @@ -36,7 +36,7 @@ public void Create_AttachesTheServicesToTheExceptionHandlerUntilDisposed() var exceptionHandler = CreateExceptionHandler(); var policyFactory = new FakePolicyFactory(() => new PolicyService(new FakePolicyReader())); var settingsFactory = new FakeSettingsFactory(() => new UserSettings()); - var factory = new BootstrapContextFactory(new FakeLoggerFactory(), policyFactory, settingsFactory, new FakeTelemetryFactory(), exceptionHandler); + var factory = new BootstrapContextFactory(new FakeLoggerFactory(), new DiagnosticLevelSwitch(), new DiagnosticLogStore(), policyFactory, settingsFactory, new FakeTelemetryFactory(), exceptionHandler); var context = factory.Create(); var telemetry = Assert.IsType(context.Telemetry); @@ -62,7 +62,7 @@ public void Create_LoadsPoliciesOnceBeforeCreatingTelemetry(bool? policy, bool p var policyFactory = new FakePolicyFactory(() => policyService); var settingsFactory = new FakeSettingsFactory(() => settings); var telemetryFactory = new FakeTelemetryFactory(); - var factory = new BootstrapContextFactory(loggerFactory, policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); + var factory = new BootstrapContextFactory(loggerFactory, new DiagnosticLevelSwitch(), new DiagnosticLogStore(), policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); Assert.Equal(0, reader.ReadCount); Assert.Equal(0, policyFactory.CreateCount); @@ -83,6 +83,22 @@ public void Create_LoadsPoliciesOnceBeforeCreatingTelemetry(bool? policy, bool p Assert.Equal(1, settingsFactory.CreateCount); } + [Fact] + public void Create_AppliesTheDiagnosticLevelAndKeepsTheDiagnosticLog() + { + var diagnosticLevel = new DiagnosticLevelSwitch(); + var diagnosticLog = new DiagnosticLogStore(); + var policyFactory = new FakePolicyFactory(() => new PolicyService(new FakePolicyReader())); + var settingsFactory = new FakeSettingsFactory(() => new UserSettings { DiagnosticLevel = DiagnosticLevelType.Verbose }); + var factory = new BootstrapContextFactory(new FakeLoggerFactory(), diagnosticLevel, diagnosticLog, policyFactory, settingsFactory, new FakeTelemetryFactory(), CreateExceptionHandler()); + + using var context = factory.Create(); + + Assert.Same(diagnosticLevel, context.DiagnosticLevel); + Assert.Same(diagnosticLog, context.DiagnosticLog); + Assert.Equal(DiagnosticLevelType.Verbose, diagnosticLevel.Level); + } + [Fact] public void Create_ReadFailurePropagatesBeforeTelemetryIsCreated() { @@ -92,7 +108,7 @@ public void Create_ReadFailurePropagatesBeforeTelemetryIsCreated() var policyFactory = new FakePolicyFactory(() => new PolicyService(reader)); var settingsFactory = new FakeSettingsFactory(() => new UserSettings()); var telemetryFactory = new FakeTelemetryFactory(); - var factory = new BootstrapContextFactory(loggerFactory, policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); + var factory = new BootstrapContextFactory(loggerFactory, new DiagnosticLevelSwitch(), new DiagnosticLogStore(), policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); Assert.Same(failure, Assert.Throws(() => factory.Create())); Assert.Equal(0, settingsFactory.CreateCount); @@ -108,7 +124,7 @@ public void Create_PolicyCreationFailurePropagatesBeforeCreatingOtherServices() var policyFactory = new FakePolicyFactory(() => throw failure); var settingsFactory = new FakeSettingsFactory(() => new UserSettings()); var telemetryFactory = new FakeTelemetryFactory(); - var factory = new BootstrapContextFactory(loggerFactory, policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); + var factory = new BootstrapContextFactory(loggerFactory, new DiagnosticLevelSwitch(), new DiagnosticLogStore(), policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); Assert.Same(failure, Assert.Throws(() => factory.Create())); Assert.Equal(0, settingsFactory.CreateCount); @@ -124,7 +140,7 @@ public void Create_SettingsCreationFailureUsesDefaultsCreatesTelemetryAndLogsErr var policyFactory = new FakePolicyFactory(() => new PolicyService(new FakePolicyReader())); var settingsFactory = new FakeSettingsFactory(() => throw failure); var telemetryFactory = new FakeTelemetryFactory(); - var factory = new BootstrapContextFactory(loggerFactory, policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); + var factory = new BootstrapContextFactory(loggerFactory, new DiagnosticLevelSwitch(), new DiagnosticLogStore(), policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); using var context = factory.Create(); @@ -146,7 +162,7 @@ public void Create_TelemetryFailureUsesDisabledServiceAndLogsError() var policyFactory = new FakePolicyFactory(() => new PolicyService(new FakePolicyReader())); var settingsFactory = new FakeSettingsFactory(() => new UserSettings()); var telemetryFactory = new FakeTelemetryFactory { Failure = failure }; - var factory = new BootstrapContextFactory(loggerFactory, policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); + var factory = new BootstrapContextFactory(loggerFactory, new DiagnosticLevelSwitch(), new DiagnosticLogStore(), policyFactory, settingsFactory, telemetryFactory, CreateExceptionHandler()); using var context = factory.Create(); diff --git a/test/Bravo.Tests/Host/BravoApplicationBuilderTests.cs b/test/Bravo.Tests/Host/BravoApplicationBuilderTests.cs index a4ed3d0f..a3b5b2b0 100644 --- a/test/Bravo.Tests/Host/BravoApplicationBuilderTests.cs +++ b/test/Bravo.Tests/Host/BravoApplicationBuilderTests.cs @@ -4,6 +4,7 @@ using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Host; using Sqlbi.Bravo.Infrastructure.Configuration.Settings; +using Sqlbi.Bravo.Infrastructure.Diagnostics; using Sqlbi.Bravo.Infrastructure.Policies; using Sqlbi.Bravo.Infrastructure.SingleInstance; using Sqlbi.Bravo.Infrastructure.Telemetry; @@ -20,16 +21,20 @@ public void Build_ResolvesTheExistingInstancesWithoutOwningTheirLifetime() var telemetry = new FakeTelemetry(); var policies = new PolicyService(new FakePolicyReader()); var settings = new UserSettings(); + var diagnosticLevel = new DiagnosticLevelSwitch(); + var diagnosticLog = new DiagnosticLogStore(); var options = TestInstanceOptions.Create(); Assert.True(SingleInstanceServer.TryStart(options, out var instanceServer)); using (instanceServer) - using (var bootstrap = new BootstrapContext(loggerFactory, policies, settings, telemetry)) + using (var bootstrap = new BootstrapContext(loggerFactory, diagnosticLevel, diagnosticLog, policies, settings, telemetry)) { using (var application = BravoApplication.CreateBuilder(bootstrap, instanceServer).Build()) { Assert.Same(loggerFactory, application.Services.GetRequiredService()); + Assert.Same(diagnosticLevel, application.Services.GetRequiredService()); + Assert.Same(diagnosticLog, application.Services.GetRequiredService()); Assert.Same(telemetry, application.Services.GetRequiredService()); Assert.Same(policies, application.Services.GetRequiredService()); Assert.Same(settings, application.Services.GetRequiredService()); diff --git a/test/Bravo.Tests/Host/BravoLoggingBuilderExtensionsTests.cs b/test/Bravo.Tests/Host/BravoLoggingBuilderExtensionsTests.cs new file mode 100644 index 00000000..acabb5eb --- /dev/null +++ b/test/Bravo.Tests/Host/BravoLoggingBuilderExtensionsTests.cs @@ -0,0 +1,57 @@ +using System; +using Bravo.Tests.Infrastructure.Diagnostics; +using Microsoft.Extensions.Logging; +using Sqlbi.Bravo.Host; +using Sqlbi.Bravo.Infrastructure.Configuration.Settings; +using Sqlbi.Bravo.Infrastructure.Diagnostics; +using Xunit; + +namespace Bravo.Tests.Host; + +public class BravoLoggingBuilderExtensionsTests +{ + [Theory] + [InlineData(DiagnosticLevelType.None)] + [InlineData(DiagnosticLevelType.Basic)] + public void AddBravoDiagnosticLog_DropsInformationBelowTheVerboseLevel(DiagnosticLevelType level) + { + var store = new DiagnosticLogStore(); + using var loggerFactory = CreateLoggerFactory(store, new DiagnosticLevelSwitch(level)); + var logger = loggerFactory.CreateLogger("Sqlbi.Bravo.Test"); + + logger.LogInformation("dropped"); + logger.LogWarning("kept"); + + Assert.False(logger.IsEnabled(LogLevel.Information)); + Assert.Equal("kept", Assert.Single(store.Read(after: 0).Entries).Message); + } + + [Fact] + public void AddBravoDiagnosticLog_FollowsALevelChangedAfterTheLoggerWasCreated() + { + var levelSwitch = new DiagnosticLevelSwitch(DiagnosticLevelType.Basic); + using var loggerFactory = CreateLoggerFactory(new DiagnosticLogStore(), levelSwitch); + var logger = loggerFactory.CreateLogger("Sqlbi.Bravo.Test"); + + levelSwitch.Level = DiagnosticLevelType.Verbose; + + Assert.True(logger.IsEnabled(LogLevel.Information)); + } + + [Fact] + public void AddBravoDiagnosticLog_KeepsFrameworkCategoriesAtWarningAtTheVerboseLevel() + { + var levelSwitch = new DiagnosticLevelSwitch(DiagnosticLevelType.Verbose); + using var loggerFactory = CreateLoggerFactory(new DiagnosticLogStore(), levelSwitch); + var logger = loggerFactory.CreateLogger("Microsoft.AspNetCore.Hosting.Diagnostics"); + + Assert.False(logger.IsEnabled(LogLevel.Information)); + Assert.True(logger.IsEnabled(LogLevel.Warning)); + } + + private static ILoggerFactory CreateLoggerFactory(DiagnosticLogStore store, DiagnosticLevelSwitch levelSwitch) + { + var timeProvider = new FixedTimeProvider(DateTimeOffset.UnixEpoch); + return LoggerFactory.Create((builder) => builder.AddBravoDiagnosticLog(store, levelSwitch, timeProvider)); + } +} diff --git a/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogExceptionTests.cs b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogExceptionTests.cs new file mode 100644 index 00000000..b583d7a0 --- /dev/null +++ b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogExceptionTests.cs @@ -0,0 +1,62 @@ +using System; +using System.Linq; +using Sqlbi.Bravo.Infrastructure.Diagnostics; +using Xunit; + +namespace Bravo.Tests.Infrastructure.Diagnostics; + +public class DiagnosticLogExceptionTests +{ + [Fact] + public void CreateChain_ReturnsNullWithoutAnException() + { + Assert.Null(DiagnosticLogException.CreateChain(null)); + } + + [Fact] + public void CreateChain_FollowsTheInnerExceptionsOutermostFirst() + { + var exception = new InvalidOperationException("outer", new TimeoutException("inner")); + + var chain = DiagnosticLogException.CreateChain(exception); + + Assert.NotNull(chain); + Assert.Equal(["outer", "inner"], chain.Select((e) => e.Message)); + Assert.Equal(typeof(TimeoutException).FullName, chain[1].Type); + } + + [Fact] + public void CreateChain_KeepsEveryInnerExceptionOfAnAggregateDepthFirst() + { + var first = new InvalidOperationException("first", new TimeoutException("first inner")); + var exception = new AggregateException("aggregate", first, new ArgumentException("second")); + + var chain = DiagnosticLogException.CreateChain(exception); + + Assert.NotNull(chain); + Assert.Equal(["aggregate (first) (second)", "first", "first inner", "second"], chain.Select((e) => e.Message)); + } + + [Fact] + public void CreateChain_KeepsThePropertiesTheExceptionTypeAdds() + { + var exception = new ServiceException("sign-in failed") { ErrorCode = "invalid_grant", StatusCode = 400 }; + + var chain = DiagnosticLogException.CreateChain(exception); + + Assert.NotNull(chain); + var details = Assert.Single(chain).Details; + Assert.NotNull(details); + Assert.Equal("invalid_grant", details["ErrorCode"]); + Assert.Equal("400", details["StatusCode"]); + Assert.False(details.ContainsKey(nameof(Exception.HResult))); + Assert.False(details.ContainsKey(nameof(ServiceException.Inner))); + } + + private sealed class ServiceException(string message) : Exception(message) + { + public string? ErrorCode { get; init; } + public int StatusCode { get; init; } + public Exception? Inner => InnerException; + } +} diff --git a/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogProviderTests.cs b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogProviderTests.cs new file mode 100644 index 00000000..ced50a69 --- /dev/null +++ b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogProviderTests.cs @@ -0,0 +1,91 @@ +using System; +using Microsoft.Extensions.Logging; +using Sqlbi.Bravo.Infrastructure.Diagnostics; +using Xunit; + +namespace Bravo.Tests.Infrastructure.Diagnostics; + +public class DiagnosticLogProviderTests +{ + private static readonly DateTimeOffset s_now = new(2026, 10, 21, 8, 30, 0, TimeSpan.Zero); + + [Fact] + public void Log_StoresTheRecordWithItsTemplateAndProperties() + { + var store = new DiagnosticLogStore(); + using var loggerFactory = CreateLoggerFactory(store); + var logger = loggerFactory.CreateLogger("Sqlbi.Bravo.Test"); + + logger.Log(LogLevel.Information, new EventId(7, "LogPayloadReceived"), "Payload received: {Payload}", "[1,2]"); + + var entry = Assert.Single(store.Read(after: 0).Entries); + Assert.Equal(s_now, entry.Timestamp); + Assert.Equal(LogLevel.Information, entry.Level); + Assert.Equal("Sqlbi.Bravo.Test", entry.Category); + Assert.Equal(7, entry.EventId); + Assert.Equal("LogPayloadReceived", entry.EventName); + Assert.Equal("Payload received: [1,2]", entry.Message); + Assert.Equal("Payload received: {Payload}", entry.Template); + Assert.NotNull(entry.Properties); + Assert.Equal("[1,2]", entry.Properties["Payload"]); + Assert.Null(entry.Exception); + } + + [Fact] + public void Log_OmitsTheTemplateOfAMessageWithoutPlaceholders() + { + var store = new DiagnosticLogStore(); + using var loggerFactory = CreateLoggerFactory(store); + var logger = loggerFactory.CreateLogger("Sqlbi.Bravo.Test"); + + logger.LogWarning("plain message"); + + var entry = Assert.Single(store.Read(after: 0).Entries); + Assert.Equal("plain message", entry.Message); + Assert.Null(entry.Template); + Assert.Null(entry.Properties); + } + + [Fact] + public void Log_StoresTheExceptionChainOutermostFirst() + { + var store = new DiagnosticLogStore(); + using var loggerFactory = CreateLoggerFactory(store); + var logger = loggerFactory.CreateLogger("Sqlbi.Bravo.Test"); + var exception = new InvalidOperationException("outer", new TimeoutException("inner")); + + logger.LogError(exception, "the message"); + + var entry = Assert.Single(store.Read(after: 0).Entries); + Assert.Equal("the message", entry.Message); + Assert.NotNull(entry.Exception); + Assert.Collection( + entry.Exception, + (outer) => Assert.Equal((typeof(InvalidOperationException).FullName, "outer"), (outer.Type, outer.Message)), + (inner) => Assert.Equal((typeof(TimeoutException).FullName, "inner"), (inner.Type, inner.Message))); + } + + [Fact] + public void Log_KeepsTheTextInsideSensitiveTagsForThePane() + { + var store = new DiagnosticLogStore(); + using var loggerFactory = CreateLoggerFactory(store); + var logger = loggerFactory.CreateLogger("Sqlbi.Bravo.Test"); + var exception = new InvalidOperationException("user alice denied"); + + logger.LogWarning(exception, "Database {Database} not found", "Sales"); + + var entry = Assert.Single(store.Read(after: 0).Entries); + Assert.Equal("Database Sales not found", entry.Message); + Assert.NotNull(entry.Properties); + Assert.Equal("Sales", entry.Properties["Database"]); + Assert.NotNull(entry.Exception); + Assert.Equal("user alice denied", entry.Exception[0].Message); + } + + private static ILoggerFactory CreateLoggerFactory(DiagnosticLogStore store) + { + var timeProvider = new FixedTimeProvider(s_now); + return LoggerFactory.Create((builder) => builder.AddDiagnosticLog(store, timeProvider)); + } +} diff --git a/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogStoreTests.cs b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogStoreTests.cs new file mode 100644 index 00000000..25439417 --- /dev/null +++ b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogStoreTests.cs @@ -0,0 +1,130 @@ +using System.Linq; +using Sqlbi.Bravo.Infrastructure.Diagnostics; +using Xunit; + +namespace Bravo.Tests.Infrastructure.Diagnostics; + +public class DiagnosticLogStoreTests +{ + [Fact] + public void Read_ReturnsEveryRecordHeldWhenTheCursorIsZero() + { + var store = new DiagnosticLogStore(); + + store.Add(TestLogEntries.Create("first")); + store.Add(TestLogEntries.Create("second")); + + var page = store.Read(after: 0); + Assert.Equal(["first", "second"], page.Entries.Select((e) => e.Message)); + Assert.Equal(2, page.LastSequence); + Assert.Equal(0, page.DroppedCount); + } + + [Fact] + public void Read_ReturnsOnlyTheRecordsAfterTheCursor() + { + var store = new DiagnosticLogStore(); + store.Add(TestLogEntries.Create("first")); + store.Add(TestLogEntries.Create("second")); + store.Add(TestLogEntries.Create("third")); + + var page = store.Read(after: 2); + + Assert.Equal("third", Assert.Single(page.Entries).Message); + Assert.Equal(3, page.LastSequence); + } + + [Fact] + public void Read_DoesNotConsumeTheRecords() + { + var store = new DiagnosticLogStore(); + store.Add(TestLogEntries.Create("kept")); + + store.Read(after: 0); + var page = store.Read(after: 0); + + Assert.Equal("kept", Assert.Single(page.Entries).Message); + } + + [Fact] + public void Read_ReportsTheRecordsEvictedAfterTheCursor() + { + var store = new DiagnosticLogStore(capacity: 2); + store.Add(TestLogEntries.Create("first")); + store.Add(TestLogEntries.Create("second")); + store.Add(TestLogEntries.Create("third")); + store.Add(TestLogEntries.Create("fourth")); + + var page = store.Read(after: 0); + + Assert.Equal(["third", "fourth"], page.Entries.Select((e) => e.Message)); + Assert.Equal(2, page.DroppedCount); + Assert.Equal(0, store.Read(after: 2).DroppedCount); + } + + [Fact] + public void Read_ReturnsTheNewestRecordsUpToTheMaximumCount() + { + var store = new DiagnosticLogStore(); + store.Add(TestLogEntries.Create("first")); + store.Add(TestLogEntries.Create("second")); + store.Add(TestLogEntries.Create("third")); + + var page = store.Read(after: 0, maxCount: 2); + + Assert.Equal(["second", "third"], page.Entries.Select((e) => e.Message)); + Assert.Equal(1, page.DroppedCount); + Assert.Equal(3, page.LastSequence); + } + + [Fact] + public void Add_EvictsTheOldestRecordsBeyondTheCharacterBudget() + { + var store = new DiagnosticLogStore(characterBudget: 20); + store.Add(TestLogEntries.Create(new string('a', 10))); + store.Add(TestLogEntries.Create(new string('b', 10))); + store.Add(TestLogEntries.Create(new string('c', 10))); + + var page = store.Read(after: 0); + + Assert.Equal([new string('c', 10)], page.Entries.Select((e) => e.Message)); + Assert.Equal(2, page.DroppedCount); + } + + [Fact] + public void Add_KeepsTheNewestRecordEvenWhenItExceedsTheCharacterBudget() + { + var store = new DiagnosticLogStore(characterBudget: 5); + store.Add(TestLogEntries.Create("small")); + store.Add(TestLogEntries.Create(new string('x', 100))); + + var page = store.Read(after: 0); + + Assert.Equal(new string('x', 100), Assert.Single(page.Entries).Message); + } + + [Fact] + public void Read_ToleratesANegativeCursor() + { + var store = new DiagnosticLogStore(); + store.Add(TestLogEntries.Create("only")); + + var page = store.Read(after: -5); + + Assert.Single(page.Entries); + Assert.Equal(0, page.DroppedCount); + } + + [Fact] + public void Read_ReturnsNothingForACursorBeyondTheLastSequence() + { + var store = new DiagnosticLogStore(); + store.Add(TestLogEntries.Create("only")); + + var page = store.Read(after: 10); + + Assert.Empty(page.Entries); + Assert.Equal(1, page.LastSequence); + Assert.Equal(0, page.DroppedCount); + } +} diff --git a/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticMessageLoggerProviderTests.cs b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticMessageLoggerProviderTests.cs deleted file mode 100644 index a339ef5d..00000000 --- a/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticMessageLoggerProviderTests.cs +++ /dev/null @@ -1,56 +0,0 @@ -using System; -using System.Linq; -using Microsoft.Extensions.Logging; -using Sqlbi.Bravo.Infrastructure; -using Sqlbi.Bravo.Infrastructure.Diagnostics; -using Sqlbi.Bravo.Models; -using Xunit; - -namespace Bravo.Tests.Infrastructure.Diagnostics; - -public class DiagnosticMessageLoggerProviderTests -{ - [Theory] - [InlineData(LogLevel.Critical, DiagnosticMessageSeverity.Error)] - [InlineData(LogLevel.Error, DiagnosticMessageSeverity.Error)] - [InlineData(LogLevel.Warning, DiagnosticMessageSeverity.Warning)] - [InlineData(LogLevel.Information, DiagnosticMessageSeverity.None)] - public void Log_MapsTheLevelToTheMessageSeverity(LogLevel logLevel, DiagnosticMessageSeverity expected) - { - var category = $"{nameof(Log_MapsTheLevelToTheMessageSeverity)}.{logLevel}"; - using var provider = new DiagnosticMessageLoggerProvider(); - var logger = provider.CreateLogger(category); - - logger.Log(logLevel, default, "the message", null, (state, _) => state); - - var message = FindMessage(category); - Assert.Equal(expected, message.Severity); - Assert.Equal(DiagnosticMessageType.Text, message.Type); - Assert.Equal("the message", message.Content); - } - - [Fact] - public void Log_AppendsTheExceptionToTheContent() - { - var category = nameof(Log_AppendsTheExceptionToTheContent); - var exception = new InvalidOperationException("policies unavailable"); - using var provider = new DiagnosticMessageLoggerProvider(); - var logger = provider.CreateLogger(category); - - logger.LogError(exception, "the message"); - - var message = FindMessage(category); - Assert.StartsWith("the message", message.Content); - Assert.Contains("policies unavailable", message.Content); - } - - private static DiagnosticMessage FindMessage(string category) - { - var message = AppEnvironment.Diagnostics.Values.SingleOrDefault((m) => m.Name == $"[HOST] {category}"); - - Assert.NotNull(message); - Assert.NotNull(message.Content); - - return message; - } -} diff --git a/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticsFakes.cs b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticsFakes.cs index 3960d0eb..c20f47fa 100644 --- a/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticsFakes.cs +++ b/test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticsFakes.cs @@ -1,4 +1,5 @@ using System; +using Microsoft.Extensions.Logging; using Sqlbi.Bravo.Infrastructure.Diagnostics; using Sqlbi.Bravo.Infrastructure.Telemetry; @@ -21,3 +22,18 @@ public void Show(ErrorReport report, ITelemetryService? telemetry) throw ExceptionToThrow; } } + +internal sealed class FixedTimeProvider(DateTimeOffset now) : TimeProvider +{ + private readonly DateTimeOffset _now = now; + + public override DateTimeOffset GetUtcNow() => _now; +} + +internal static class TestLogEntries +{ + public static DiagnosticLogEntry Create(string message, LogLevel level = LogLevel.Warning) + { + return new DiagnosticLogEntry(DateTimeOffset.UnixEpoch, level, "Test", 0, null, message, null, null, null); + } +} diff --git a/test/Bravo.Tests/Infrastructure/Diagnostics/ErrorReportTests.cs b/test/Bravo.Tests/Infrastructure/Diagnostics/ErrorReportTests.cs new file mode 100644 index 00000000..133ba0ef --- /dev/null +++ b/test/Bravo.Tests/Infrastructure/Diagnostics/ErrorReportTests.cs @@ -0,0 +1,20 @@ +using System; +using Sqlbi.Bravo.Infrastructure.Diagnostics; +using Xunit; + +namespace Bravo.Tests.Infrastructure.Diagnostics; + +public class ErrorReportTests +{ + [Fact] + public void Text_HasTheTitleTheEnvironmentAndTheException() + { + var report = ErrorReport.Create(new InvalidOperationException("startup failed")); + + Assert.StartsWith("# Bravo for Power BI — Error Report", report.Text); + Assert.Contains("## Environment information", report.Text); + Assert.Contains("\"application\"", report.Text); + Assert.Contains("## Exception details", report.Text); + Assert.Contains("System.InvalidOperationException: startup failed", report.Text); + } +} diff --git a/test/Bravo.Tests/Infrastructure/Extensions/HostingExtensionsTests.cs b/test/Bravo.Tests/Infrastructure/Extensions/HostingExtensionsTests.cs new file mode 100644 index 00000000..d1a64e08 --- /dev/null +++ b/test/Bravo.Tests/Infrastructure/Extensions/HostingExtensionsTests.cs @@ -0,0 +1,33 @@ +using System; +using Bravo.Tests.Host; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Sqlbi.Bravo.Infrastructure.Extensions; +using Sqlbi.Bravo.Infrastructure.Telemetry; +using Xunit; + +namespace Bravo.Tests.Infrastructure.Extensions; + +public class HostingExtensionsTests +{ + [Fact] + public void ReportMappedException_LogsAndTracksTheException() + { + var loggerFactory = new FakeLoggerFactory(); + var telemetry = new FakeTelemetry(); + var services = new ServiceCollection() + .AddSingleton(loggerFactory) + .AddSingleton(telemetry) + .BuildServiceProvider(); + var context = new DefaultHttpContext { RequestServices = services }; + var exception = new InvalidOperationException("connection failed"); + + HostingExtensions.ReportMappedException(context, exception); + + var entry = Assert.Single(loggerFactory.Entries); + Assert.Equal(LogLevel.Information, entry.Level); + Assert.Same(exception, entry.Exception); + Assert.Same(exception, Assert.Single(telemetry.Exceptions)); + } +} diff --git a/test/Bravo.Tests/Infrastructure/Telemetry/SensitiveTagsTests.cs b/test/Bravo.Tests/Infrastructure/Telemetry/SensitiveTagsTests.cs new file mode 100644 index 00000000..861627a7 --- /dev/null +++ b/test/Bravo.Tests/Infrastructure/Telemetry/SensitiveTagsTests.cs @@ -0,0 +1,54 @@ +using System; +using System.IO; +using System.Linq; +using Sqlbi.Bravo.Infrastructure.Telemetry; +using Xunit; + +namespace Bravo.Tests.Infrastructure.Telemetry; + +// The tag cases are covered through DefaultTelemetryProcessorTests; these are the inputs telemetry never passes. +public class SensitiveTagsTests +{ + [Fact] + public void Redact_ReturnsAnEmptyStringForNull() + { + Assert.Equal(string.Empty, SensitiveTags.Redact(null)); + } + + [Fact] + public void Redact_ReturnsAnEmptyStringUnchanged() + { + Assert.Equal(string.Empty, SensitiveTags.Redact(string.Empty)); + } + + [Fact] + public void Redact_WithholdsTheWholeTextWhenTheScanTimesOut() + { + // Unclosed tags make every opening scan to the end: 20,000 already exceed the one-second limit. + var input = string.Concat(Enumerable.Repeat("secret ", 50_000)); + + Assert.Equal("[REDACTED]", SensitiveTags.Redact(input)); + } + + [Fact] + public void TagNames_MatchTheTagsTheFrontendRemovesWhenItCopiesAMessage() + { + var utilsPath = Path.Combine(FindRepositoryRoot(), "src", "Scripts", "helpers", "utils.ts"); + var utils = File.ReadAllText(utilsPath); + + Assert.Contains($"/<({SensitiveTags.TagNames})>", utils); + } + + private static string FindRepositoryRoot() + { + for (var directory = new DirectoryInfo(AppContext.BaseDirectory); directory is not null; directory = directory.Parent) + { + if (File.Exists(Path.Combine(directory.FullName, "Bravo.sln"))) + { + return directory.FullName; + } + } + + throw new InvalidOperationException("Bravo.sln was not found above the test output folder."); + } +}