From 65dc02dac2b330d997c5cc14b1f9877aeddb6613 Mon Sep 17 00:00:00 2001 From: Alberto Spelta Date: Thu, 22 Oct 2026 01:07:02 +0200 Subject: [PATCH] refactor: route host diagnostics through ILogger and a bounded store Every AppEnvironment.AddDiagnostics call is now a [LoggerMessage] method; static call sites log in their caller or take an ILogger. AddDiagnostics, IsDiagnosticLevelVerbose, AppEnvironment.Diagnostics and DiagnosticMessage are removed. DiagnosticLevelSwitch carries the user's diagnostic level into a logger filter rule: the pane store receives Information only at Verbose, while Microsoft and System categories stay at Warning. The bootstrap applies the saved level and UpdateOptions applies a changed one after every save attempt. DiagnosticLogStore keeps the last 1000 records, bounded by text size too, with template, placeholder values and the exception chain (aggregate inners and the properties each exception type adds). GetDiagnostics takes a cursor and a maximum count instead of marking records as read, so a reload of the pane loses no host record. The pane polls at every level except None, shows JSON values as a tree and highlights records with an exception. The catch-all problem details mapping no longer logs, since the middleware logs 500 responses; mapped exceptions are logged and tracked through one method. The per-message copy redacts the same five sensitive tags as telemetry, and a test keeps the two tag lists aligned. --- docs/design/diagnostics.md | 58 ++++++-- src/Controllers/ApplicationController.cs | 51 ++++--- src/Controllers/AuthenticationController.cs | 6 - .../TemplateDevelopmentController.cs | 7 +- src/Host/BootstrapContext.cs | 7 + src/Host/BootstrapContextFactory.cs | 18 ++- src/Host/BravoLoggingBuilderExtensions.cs | 20 ++- src/Host/BravoServiceCollectionExtensions.cs | 2 + src/Infrastructure/AppEnvironment.cs | 19 --- src/Infrastructure/AppWindow.Log.cs | 18 +++ src/Infrastructure/AppWindow.cs | 24 ++-- .../Diagnostics/DiagnosticLevelSwitch.cs | 24 ++++ .../DiagnosticLogBuilderExtensions.cs | 20 +++ .../Diagnostics/DiagnosticLogEntry.cs | 22 +++ .../Diagnostics/DiagnosticLogException.cs | 105 ++++++++++++++ .../Diagnostics/DiagnosticLogPage.cs | 10 ++ .../Diagnostics/DiagnosticLogProvider.cs | 87 ++++++++++++ .../Diagnostics/DiagnosticLogStore.cs | 116 ++++++++++++++++ .../Diagnostics/DiagnosticMessageLogger.cs | 53 ------- .../DiagnosticMessageLoggerProvider.cs | 16 --- .../Extensions/HostingExtensions.Log.cs | 13 ++ .../Extensions/HostingExtensions.cs | 51 ++++--- .../Helpers/CommonHelper.Log.cs | 9 ++ src/Infrastructure/Helpers/CommonHelper.cs | 8 +- .../Helpers/TokenCacheHelper.Log.cs | 10 ++ .../Helpers/TokenCacheHelper.cs | 14 +- .../Messages/AppInstanceStartupMessage.cs | 3 - .../CloudAuthenticationClient.cs | 6 +- .../CloudAuthenticationService.Log.cs | 9 ++ .../CloudAuthenticationService.cs | 13 +- .../PowerBI/Cloud/CloudApiClient.Log.cs | 21 +++ .../PowerBI/Cloud/CloudApiClient.cs | 25 ++-- .../CloudConfigurationService.Log.cs | 15 ++ .../CloudConfigurationService.cs | 27 ++-- .../Services/ConnectionWrapper.cs | 24 ++-- .../DaxTemplate/DaxTemplateManager.cs | 9 +- .../Services/PowerBI/PBIDesktopService.cs | 7 +- .../Services/TabularConnectionWrapper.Log.cs | 9 ++ .../Telemetry/DefaultTelemetryProcessor.cs | 22 +-- src/Infrastructure/Telemetry/SensitiveTags.cs | 39 ++++++ src/Models/DiagnosticMessage.cs | 52 ------- src/Models/ManageDates/DateConfiguration.cs | 8 +- .../DateConfigurationExtensions.Log.cs | 10 ++ src/Models/PBIDesktopReport.Log.cs | 10 ++ src/Models/PBIDesktopReport.cs | 14 +- src/Scripts/controllers/host.ts | 48 ++++--- src/Scripts/controllers/logger.ts | 60 ++++++-- src/Scripts/helpers/utils.ts | 3 +- src/Services/AnalyzeModelService.cs | 13 +- src/Services/ExportDataService.Log.cs | 9 ++ src/Services/ExportDataService.cs | 16 +-- src/Services/FormatDaxService.cs | 9 +- src/Services/ManageDatesService.cs | 19 +-- src/Services/TemplateDevelopmentService.cs | 11 +- .../Controllers/ApplicationControllerTests.cs | 51 +++++++ .../Bravo.Tests/Host/BootstrapContextTests.cs | 30 +++- .../Host/BravoApplicationBuilderTests.cs | 7 +- .../BravoLoggingBuilderExtensionsTests.cs | 57 ++++++++ .../DiagnosticLogExceptionTests.cs | 62 +++++++++ .../Diagnostics/DiagnosticLogProviderTests.cs | 91 ++++++++++++ .../Diagnostics/DiagnosticLogStoreTests.cs | 130 ++++++++++++++++++ .../DiagnosticMessageLoggerProviderTests.cs | 56 -------- .../Diagnostics/DiagnosticsFakes.cs | 16 +++ .../Diagnostics/ErrorReportTests.cs | 20 +++ .../Extensions/HostingExtensionsTests.cs | 33 +++++ .../Telemetry/SensitiveTagsTests.cs | 54 ++++++++ 66 files changed, 1474 insertions(+), 432 deletions(-) create mode 100644 src/Infrastructure/AppWindow.Log.cs create mode 100644 src/Infrastructure/Diagnostics/DiagnosticLevelSwitch.cs create mode 100644 src/Infrastructure/Diagnostics/DiagnosticLogBuilderExtensions.cs create mode 100644 src/Infrastructure/Diagnostics/DiagnosticLogEntry.cs create mode 100644 src/Infrastructure/Diagnostics/DiagnosticLogException.cs create mode 100644 src/Infrastructure/Diagnostics/DiagnosticLogPage.cs create mode 100644 src/Infrastructure/Diagnostics/DiagnosticLogProvider.cs create mode 100644 src/Infrastructure/Diagnostics/DiagnosticLogStore.cs delete mode 100644 src/Infrastructure/Diagnostics/DiagnosticMessageLogger.cs delete mode 100644 src/Infrastructure/Diagnostics/DiagnosticMessageLoggerProvider.cs create mode 100644 src/Infrastructure/Extensions/HostingExtensions.Log.cs create mode 100644 src/Infrastructure/Helpers/CommonHelper.Log.cs create mode 100644 src/Infrastructure/Helpers/TokenCacheHelper.Log.cs create mode 100644 src/Infrastructure/PowerBI/Cloud/Authentication/CloudAuthenticationService.Log.cs create mode 100644 src/Infrastructure/PowerBI/Cloud/CloudApiClient.Log.cs create mode 100644 src/Infrastructure/PowerBI/Cloud/Configuration/CloudConfigurationService.Log.cs create mode 100644 src/Infrastructure/Services/TabularConnectionWrapper.Log.cs create mode 100644 src/Infrastructure/Telemetry/SensitiveTags.cs delete mode 100644 src/Models/DiagnosticMessage.cs create mode 100644 src/Models/ManageDates/DateConfigurationExtensions.Log.cs create mode 100644 src/Models/PBIDesktopReport.Log.cs create mode 100644 src/Services/ExportDataService.Log.cs create mode 100644 test/Bravo.Tests/Controllers/ApplicationControllerTests.cs create mode 100644 test/Bravo.Tests/Host/BravoLoggingBuilderExtensionsTests.cs create mode 100644 test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogExceptionTests.cs create mode 100644 test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogProviderTests.cs create mode 100644 test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticLogStoreTests.cs delete mode 100644 test/Bravo.Tests/Infrastructure/Diagnostics/DiagnosticMessageLoggerProviderTests.cs create mode 100644 test/Bravo.Tests/Infrastructure/Diagnostics/ErrorReportTests.cs create mode 100644 test/Bravo.Tests/Infrastructure/Extensions/HostingExtensionsTests.cs create mode 100644 test/Bravo.Tests/Infrastructure/Telemetry/SensitiveTagsTests.cs 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."); + } +}