From 97f30ad9ba6d139fa71a3bb67e04e5506cfb2bed Mon Sep 17 00:00:00 2001 From: Leendert de Borst <6917405+lanedirt@users.noreply.github.com> Date: Tue, 12 Aug 2025 17:39:26 +0200 Subject: [PATCH] Enable logging non-warnings to database log and adjust existing warning levels (#1112) * Enable logging non-warnings to database log and adjust warnings (#443) * Add log level filter (#443) * Update General.razor (#443) --- .../Main/Pages/Logging/General.razor | 181 ++++++++++++++---- .../Main/Pages/Users/Delete.razor | 2 +- .../Main/Pages/Users/View/Index.razor | 2 +- .../AliasVault.Admin/wwwroot/css/tailwind.css | 20 +- .../Handlers/DatabaseMessageStore.cs | 10 +- .../Workers/SmtpServerWorker.cs | 2 +- .../Tasks/EmailCleanupTask.cs | 6 +- .../Tasks/LogCleanupTask.cs | 6 +- .../Workers/TaskRunnerWorker.cs | 4 +- .../Tests/Admin/UserManagementTests.cs | 2 +- .../LoggingConfiguration.cs | 67 ++++++- 11 files changed, 231 insertions(+), 71 deletions(-) diff --git a/apps/server/AliasVault.Admin/Main/Pages/Logging/General.razor b/apps/server/AliasVault.Admin/Main/Pages/Logging/General.razor index 669754095..c3b40ad7d 100644 --- a/apps/server/AliasVault.Admin/Main/Pages/Logging/General.razor +++ b/apps/server/AliasVault.Admin/Main/Pages/Logging/General.razor @@ -21,13 +21,13 @@
-
+
-
+
+
+ +
@@ -59,10 +68,12 @@ else @{ string bgColor = log.Level switch { - "Information" => "bg-blue-500", - "Error" => "bg-red-500", - "Warning" => "bg-yellow-500", + "Verbose" => "bg-gray-500", "Debug" => "bg-green-500", + "Information" => "bg-blue-500", + "Warning" => "bg-yellow-500", + "Error" => "bg-red-500", + "Fatal" => "bg-red-700", _ => "bg-gray-500" }; } @@ -103,7 +114,7 @@ else private string _searchTerm = string.Empty; private string _lastSearchTerm = string.Empty; private CancellationTokenSource? _searchCancellationTokenSource; - + private string SearchTerm { get => _searchTerm; @@ -136,6 +147,21 @@ else } private List ServiceNames { get; set; } = []; + private List LogLevels { get; set; } = []; + + private string _selectedLogLevel = string.Empty; + private string SelectedLogLevel + { + get => _selectedLogLevel; + set + { + if (_selectedLogLevel != value) + { + _selectedLogLevel = value; + _ = RefreshData(); + } + } + } private string SortColumn { get; set; } = "Id"; private SortDirection SortDirection { get; set; } = SortDirection.Descending; @@ -160,7 +186,12 @@ else if (firstRender) { await using var dbContext = await DbContextFactory.CreateDbContextAsync(); - ServiceNames = await dbContext.Logs.Select(l => l.Application).Distinct().ToListAsync(); + ServiceNames = await dbContext.Logs.Select(l => l.Application).Distinct().OrderBy(x => x).ToListAsync(); + + // Get log levels and sort by severity (highest to lowest) + var levels = await dbContext.Logs.Select(l => l.Level).Distinct().ToListAsync(); + LogLevels = levels.OrderBy(GetLogLevelSeverityOrder).ToList(); + await RefreshData(CancellationToken.None); } } @@ -181,38 +212,8 @@ else await using var dbContext = await DbContextFactory.CreateDbContextAsync(cancellationToken); var query = dbContext.Logs.AsQueryable(); - query = ApplySearchTermFilter(query); - query = ApplyServiceNameFilter(query); - - // Apply sort. - switch (SortColumn) - { - case "Application": - query = SortDirection == SortDirection.Ascending - ? query.OrderBy(x => x.Application) - : query.OrderByDescending(x => x.Application); - break; - case "Message": - query = SortDirection == SortDirection.Ascending - ? query.OrderBy(x => x.Message) - : query.OrderByDescending(x => x.Message); - break; - case "Level": - query = SortDirection == SortDirection.Ascending - ? query.OrderBy(x => x.Level) - : query.OrderByDescending(x => x.Level); - break; - case "Timestamp": - query = SortDirection == SortDirection.Ascending - ? query.OrderBy(x => x.TimeStamp) - : query.OrderByDescending(x => x.TimeStamp); - break; - default: - query = SortDirection == SortDirection.Ascending - ? query.OrderBy(x => x.Id) - : query.OrderByDescending(x => x.Id); - break; - } + query = ApplyFilters(query); + query = ApplySorting(query); TotalRecords = await query.CountAsync(cancellationToken); LogList = await query @@ -235,6 +236,90 @@ else } } + /// + /// Applies all filters to the query. + /// + private IQueryable ApplyFilters(IQueryable query) + { + query = ApplySearchTermFilter(query); + query = ApplyServiceNameFilter(query); + + if (!string.IsNullOrEmpty(SelectedLogLevel)) + { + query = query.Where(x => x.Level == SelectedLogLevel); + } + + return query; + } + + /// + /// Applies sorting to the query based on SortColumn and SortDirection. + /// + private IQueryable ApplySorting(IQueryable query) + { + switch (SortColumn) + { + case "Application": + query = SortDirection == SortDirection.Ascending + ? query.OrderBy(x => x.Application) + : query.OrderByDescending(x => x.Application); + break; + case "Message": + query = SortDirection == SortDirection.Ascending + ? query.OrderBy(x => x.Message) + : query.OrderByDescending(x => x.Message); + break; + case "Level": + query = ApplyLevelSorting(query); + break; + case "Timestamp": + query = SortDirection == SortDirection.Ascending + ? query.OrderBy(x => x.TimeStamp) + : query.OrderByDescending(x => x.TimeStamp); + break; + default: + query = SortDirection == SortDirection.Ascending + ? query.OrderBy(x => x.Id) + : query.OrderByDescending(x => x.Id); + break; + } + + return query; + } + + /// + /// Applies special sorting for log levels based on severity. + /// + private IQueryable ApplyLevelSorting(IQueryable query) + { + if (SortDirection == SortDirection.Ascending) + { + // Sort from lowest severity (Verbose) to highest (Fatal) + query = query + .OrderBy(x => x.Level != "Verbose") + .ThenBy(x => x.Level != "Debug") + .ThenBy(x => x.Level != "Information") + .ThenBy(x => x.Level != "Warning") + .ThenBy(x => x.Level != "Error") + .ThenBy(x => x.Level != "Fatal") + .ThenBy(x => x.Id); + } + else + { + // Sort from highest severity (Fatal) to lowest (Verbose) + query = query + .OrderBy(x => x.Level != "Fatal") + .ThenBy(x => x.Level != "Error") + .ThenBy(x => x.Level != "Warning") + .ThenBy(x => x.Level != "Information") + .ThenBy(x => x.Level != "Debug") + .ThenBy(x => x.Level != "Verbose") + .ThenByDescending(x => x.Id); + } + + return query; + } + /// /// Applies a search term filter to the query. /// @@ -274,6 +359,24 @@ else return query; } + /// + /// Gets the severity order for a log level (lower number = higher severity). + /// Used for sorting log levels in dropdown by severity instead of alphabetically. + /// + private static int GetLogLevelSeverityOrder(string level) + { + return level switch + { + "Fatal" => 0, // Highest severity + "Error" => 1, + "Warning" => 2, + "Information" => 3, + "Debug" => 4, + "Verbose" => 5, // Lowest severity + _ => 6 + }; + } + private async Task DeleteLogsWithConfirmation() { if (await ConfirmModalService.ShowConfirmation("Confirm Delete", "Are you sure you want to delete all logs? This action cannot be undone.")) diff --git a/apps/server/AliasVault.Admin/Main/Pages/Users/Delete.razor b/apps/server/AliasVault.Admin/Main/Pages/Users/Delete.razor index 40ce9361d..c5f3bf71a 100644 --- a/apps/server/AliasVault.Admin/Main/Pages/Users/Delete.razor +++ b/apps/server/AliasVault.Admin/Main/Pages/Users/Delete.razor @@ -82,7 +82,7 @@ else GlobalLoadingSpinner.Show(); // Add log entry. - Logger.LogWarning("Deleted user {UserName} ({UserId}).", Obj.UserName, Obj.Id); + Logger.LogInformation("Deleted user {UserName} ({UserId}).", Obj.UserName, Obj.Id); await using var dbContext = await DbContextFactory.CreateDbContextAsync(); dbContext.AliasVaultUsers.Remove(Obj); diff --git a/apps/server/AliasVault.Admin/Main/Pages/Users/View/Index.razor b/apps/server/AliasVault.Admin/Main/Pages/Users/View/Index.razor index 103473120..856655fd6 100644 --- a/apps/server/AliasVault.Admin/Main/Pages/Users/View/Index.razor +++ b/apps/server/AliasVault.Admin/Main/Pages/Users/View/Index.razor @@ -648,7 +648,7 @@ Do you want to proceed with the restoration?")) { await dbContext.SaveChangesAsync(); // Add log entry for username change - Logger.LogWarning("Changed username for user {OldUsername} ({UserId}) to {NewUsername}.", oldUsername, User.Id, NewUsername); + Logger.LogInformation("Changed username for user {OldUsername} ({UserId}) to {NewUsername}.", oldUsername, User.Id, NewUsername); IsEditingUsername = false; UsernameValidationError = string.Empty; diff --git a/apps/server/AliasVault.Admin/wwwroot/css/tailwind.css b/apps/server/AliasVault.Admin/wwwroot/css/tailwind.css index 5e891aa21..d74eb48de 100644 --- a/apps/server/AliasVault.Admin/wwwroot/css/tailwind.css +++ b/apps/server/AliasVault.Admin/wwwroot/css/tailwind.css @@ -1278,16 +1278,16 @@ video { border-color: rgb(239 68 68 / var(--tw-border-opacity)); } -.border-yellow-500 { - --tw-border-opacity: 1; - border-color: rgb(234 179 8 / var(--tw-border-opacity)); -} - .border-yellow-200 { --tw-border-opacity: 1; border-color: rgb(254 240 138 / var(--tw-border-opacity)); } +.border-yellow-500 { + --tw-border-opacity: 1; + border-color: rgb(234 179 8 / var(--tw-border-opacity)); +} + .bg-blue-100 { --tw-bg-opacity: 1; background-color: rgb(219 234 254 / var(--tw-bg-opacity)); @@ -1827,6 +1827,11 @@ video { color: rgb(255 255 255 / var(--tw-text-opacity)); } +.text-yellow-600 { + --tw-text-opacity: 1; + color: rgb(202 138 4 / var(--tw-text-opacity)); +} + .text-yellow-700 { --tw-text-opacity: 1; color: rgb(161 98 7 / var(--tw-text-opacity)); @@ -1837,11 +1842,6 @@ video { color: rgb(133 77 14 / var(--tw-text-opacity)); } -.text-yellow-600 { - --tw-text-opacity: 1; - color: rgb(202 138 4 / var(--tw-text-opacity)); -} - .underline { text-decoration-line: underline; } diff --git a/apps/server/Services/AliasVault.SmtpService/Handlers/DatabaseMessageStore.cs b/apps/server/Services/AliasVault.SmtpService/Handlers/DatabaseMessageStore.cs index 328c84f84..f67c372fa 100644 --- a/apps/server/Services/AliasVault.SmtpService/Handlers/DatabaseMessageStore.cs +++ b/apps/server/Services/AliasVault.SmtpService/Handlers/DatabaseMessageStore.cs @@ -73,7 +73,7 @@ public class DatabaseMessageStore(ILogger logger, Config c if (toAddressesFailCount == toAddressesCount) { // No valid recipients given. - logger.LogInformation("No valid recipients in email, returning error to sender."); + logger.LogDebug("No valid recipients in email, returning error to sender."); return SmtpResponse.NoValidRecipientsGiven; } } @@ -311,7 +311,7 @@ public class DatabaseMessageStore(ILogger logger, Config c if (userEmailClaim is null) { // Email address has no user claim with corresponding encryption key, so we cannot process it. - logger.LogWarning( + logger.LogInformation( "Rejected email: email for {ToAddress} is not allowed. No user claim on this ToAddress.", toAddress.User + "@" + toAddress.Host); return false; @@ -321,7 +321,7 @@ public class DatabaseMessageStore(ILogger logger, Config c { // This email claim has no user attached to it (anymore), which most likely means the user has deleted // its account. We cannot process this email. - logger.LogWarning( + logger.LogInformation( "Rejected email: email for {ToAddress} is claimed but has no user associated with it. User has most likely deleted their account.", toAddress.User + "@" + toAddress.Host); return false; @@ -331,7 +331,7 @@ public class DatabaseMessageStore(ILogger logger, Config c if (userEmailClaim.Disabled) { // Email claim is disabled, so we cannot process this email. - logger.LogWarning( + logger.LogInformation( "Rejected email: email for {ToAddress} is claimed but is disabled which means the user has deleted the email alias.", toAddress.User + "@" + toAddress.Host); return false; @@ -353,7 +353,7 @@ public class DatabaseMessageStore(ILogger logger, Config c } var insertedId = await InsertEmailIntoDatabase(message, new MailAddress(toAddress.AsAddress()), userPublicKey); - logger.LogInformation( + logger.LogDebug( "Email for {ToAddress} successfully saved into database with ID {InsertedId}.", toAddress.User + "@" + toAddress.Host, insertedId); diff --git a/apps/server/Services/AliasVault.SmtpService/Workers/SmtpServerWorker.cs b/apps/server/Services/AliasVault.SmtpService/Workers/SmtpServerWorker.cs index 526c638bc..131dc94dc 100644 --- a/apps/server/Services/AliasVault.SmtpService/Workers/SmtpServerWorker.cs +++ b/apps/server/Services/AliasVault.SmtpService/Workers/SmtpServerWorker.cs @@ -17,7 +17,7 @@ public class SmtpServerWorker(ILogger logger, SmtpServer.SmtpS /// protected override async Task ExecuteAsync(CancellationToken stoppingToken) { - logger.LogWarning("AliasVault.SmtpService started at: {Time}", DateTimeOffset.Now); + logger.LogInformation("AliasVault.SmtpService started at: {Time}", DateTimeOffset.Now); // Start the SMTP server await smtpServer.StartAsync(stoppingToken); diff --git a/apps/server/Services/AliasVault.TaskRunner/Tasks/EmailCleanupTask.cs b/apps/server/Services/AliasVault.TaskRunner/Tasks/EmailCleanupTask.cs index 4994126e2..eba4b06a0 100644 --- a/apps/server/Services/AliasVault.TaskRunner/Tasks/EmailCleanupTask.cs +++ b/apps/server/Services/AliasVault.TaskRunner/Tasks/EmailCleanupTask.cs @@ -60,7 +60,7 @@ public class EmailCleanupTask : IMaintenanceTask if (globalEmailsDeleted > 0) { totalEmailsDeleted += globalEmailsDeleted; - _logger.LogWarning( + _logger.LogInformation( "Deleted {EmailCount} emails older than {Days} days (global setting)", globalEmailsDeleted, settings.EmailRetentionDays); @@ -93,7 +93,7 @@ public class EmailCleanupTask : IMaintenanceTask if (userEmailsDeleted > 0) { totalEmailsDeleted += userEmailsDeleted; - _logger.LogWarning( + _logger.LogInformation( "Deleted {EmailCount} emails older than {Days} days for user {UserName} (user-specific setting)", userEmailsDeleted, user.MaxEmailAgeDays, @@ -104,7 +104,7 @@ public class EmailCleanupTask : IMaintenanceTask if (totalEmailsDeleted > 0) { - _logger.LogWarning( + _logger.LogInformation( "Total emails deleted by age cleanup: {TotalEmails}", totalEmailsDeleted); } diff --git a/apps/server/Services/AliasVault.TaskRunner/Tasks/LogCleanupTask.cs b/apps/server/Services/AliasVault.TaskRunner/Tasks/LogCleanupTask.cs index 99f8c201b..11bea560a 100644 --- a/apps/server/Services/AliasVault.TaskRunner/Tasks/LogCleanupTask.cs +++ b/apps/server/Services/AliasVault.TaskRunner/Tasks/LogCleanupTask.cs @@ -51,14 +51,14 @@ public class LogCleanupTask : IMaintenanceTask var deletedCount = await dbContext.Logs .Where(x => x.TimeStamp < cutoffDate) .ExecuteDeleteAsync(cancellationToken); - _logger.LogWarning("Deleted {Count} general log entries older than {Days} days", deletedCount, settings.GeneralLogRetentionDays); + _logger.LogInformation("Deleted {Count} general log entries older than {Days} days", deletedCount, settings.GeneralLogRetentionDays); // Delete old task runner jobs var jobCutoffDate = DateTime.UtcNow.AddDays(-settings.GeneralLogRetentionDays); var deletedJobCount = await dbContext.TaskRunnerJobs .Where(x => x.RunDate < jobCutoffDate) .ExecuteDeleteAsync(cancellationToken); - _logger.LogWarning("Deleted {Count} task runner job entries older than {Days} days", deletedJobCount, settings.GeneralLogRetentionDays); + _logger.LogInformation("Deleted {Count} task runner job entries older than {Days} days", deletedJobCount, settings.GeneralLogRetentionDays); } if (settings.AuthLogRetentionDays > 0) @@ -67,7 +67,7 @@ public class LogCleanupTask : IMaintenanceTask var deletedCount = await dbContext.AuthLogs .Where(x => x.Timestamp < cutoffDate) .ExecuteDeleteAsync(cancellationToken); - _logger.LogWarning("Deleted {Count} auth log entries older than {Days} days", deletedCount, settings.AuthLogRetentionDays); + _logger.LogInformation("Deleted {Count} auth log entries older than {Days} days", deletedCount, settings.AuthLogRetentionDays); } } } diff --git a/apps/server/Services/AliasVault.TaskRunner/Workers/TaskRunnerWorker.cs b/apps/server/Services/AliasVault.TaskRunner/Workers/TaskRunnerWorker.cs index 95dfe0b4f..0805fbd70 100644 --- a/apps/server/Services/AliasVault.TaskRunner/Workers/TaskRunnerWorker.cs +++ b/apps/server/Services/AliasVault.TaskRunner/Workers/TaskRunnerWorker.cs @@ -29,7 +29,7 @@ public class TaskRunnerWorker( /// protected override async Task ExecuteAsync(CancellationToken stoppingToken) { - logger.LogWarning("AliasVault.TaskRunner started at: {Time}", DateTimeOffset.Now); + logger.LogInformation("AliasVault.TaskRunner started at: {Time}", DateTimeOffset.Now); while (!stoppingToken.IsCancellationRequested) { @@ -95,7 +95,7 @@ public class TaskRunnerWorker( /// The cancellation token. private async Task ExecuteMaintenanceTasks(TaskRunnerJob job, AliasServerDbContext dbContext, CancellationToken stoppingToken) { - logger.LogWarning("Starting maintenance tasks at {Time} (On-demand: {IsOnDemand})", DateTime.UtcNow, job.IsOnDemand); + logger.LogInformation("Starting maintenance tasks at {Time} (On-demand: {IsOnDemand})", DateTime.UtcNow, job.IsOnDemand); try { diff --git a/apps/server/Tests/AliasVault.E2ETests/Tests/Admin/UserManagementTests.cs b/apps/server/Tests/AliasVault.E2ETests/Tests/Admin/UserManagementTests.cs index a435a8cd8..7d02f6c58 100644 --- a/apps/server/Tests/AliasVault.E2ETests/Tests/Admin/UserManagementTests.cs +++ b/apps/server/Tests/AliasVault.E2ETests/Tests/Admin/UserManagementTests.cs @@ -224,7 +224,7 @@ public class UserManagementTests : AdminPlaywrightTest Assert.Multiple(() => { Assert.That(logEntry, Is.Not.Null, "Username change log entry should exist"); - Assert.That(logEntry!.Level, Is.EqualTo("Warning"), "Log level should be Warning"); + Assert.That(logEntry!.Level, Is.EqualTo("Information"), "Log level should be Information"); Assert.That(logEntry.Message, Does.Contain("Changed username for user"), "Log message should contain username change text"); Assert.That(logEntry.Message, Does.Contain(originalUsername), "Log message should contain old username"); Assert.That(logEntry.Message, Does.Contain(_newUserEmail), "Log message should contain new username"); diff --git a/apps/server/Utilities/AliasVault.Logging/LoggingConfiguration.cs b/apps/server/Utilities/AliasVault.Logging/LoggingConfiguration.cs index 283f7f3a1..2558cc60b 100644 --- a/apps/server/Utilities/AliasVault.Logging/LoggingConfiguration.cs +++ b/apps/server/Utilities/AliasVault.Logging/LoggingConfiguration.cs @@ -21,6 +21,35 @@ using Serilog.Filters; /// public static class LoggingConfiguration { + private const string SourceContextKey = "SourceContext"; + + /// + /// List of source contexts that are allowed to log Information level to the database. + /// These are important operational events that should be persisted to the database (in addition to file logging). + /// + private static readonly HashSet AllowedInformationSourcesForDatabase = new() + { + // Service lifecycle events + "AliasVault.TaskRunner.Workers.TaskRunnerWorker", + "AliasVault.SmtpService.Workers.SmtpServerWorker", + + // Task completion events + "AliasVault.TaskRunner.Tasks.EmailCleanupTask", + "AliasVault.TaskRunner.Tasks.LogCleanupTask", + + // Admin actions + "AliasVault.Admin.Main.Pages.Users.Delete", + "AliasVault.Admin.Main.Pages.Account.Manage.Disable2fa", + "AliasVault.Admin.Main.Pages.Account.Manage.EnableAuthenticator", + "AliasVault.Admin.Auth.Pages.Login", + "AliasVault.Admin.Auth.Pages.LoginWith2fa", + "AliasVault.Admin.Auth.Pages.LoginWithRecoveryCode", + "AliasVault.Admin.Main.Pages.Users.View.Index", + + // Email processing events + "AliasVault.SmtpService.Handlers.DatabaseMessageStore", + }; + /// /// Configures Serilog logging for the application. /// @@ -56,10 +85,12 @@ public static class LoggingConfiguration rollingInterval: RollingInterval.Day, outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {SourceContext} {Message:lj} {Properties:j}{NewLine}{Exception}")) - // Log all warning and above to database via EF core except for: - // - Microsoft.EntityFrameworkCore logsas this would create a loop. + // Log to database: + // - All warnings and above + // - Specific Information logs from allowed sources + // Exclude Microsoft.EntityFrameworkCore logs to prevent loops .WriteTo.Logger(lc => lc - .Filter.ByIncludingOnly(evt => evt.Level >= LogEventLevel.Warning) + .Filter.ByIncludingOnly(evt => ShouldLogToDatabase(evt)) .Filter.ByExcluding(Matching.FromSource("Microsoft.EntityFrameworkCore")) .WriteTo.Sink(new DatabaseSink(CultureInfo.InvariantCulture, () => services.BuildServiceProvider().GetRequiredService>(), applicationName))) .CreateLogger()); @@ -67,6 +98,32 @@ public static class LoggingConfiguration return services; } + /// + /// Determines if a log event should be written to the database. + /// + /// The log event to check. + /// True if the event should be logged to database, false otherwise. + private static bool ShouldLogToDatabase(LogEvent evt) + { + // Always log warnings and above + if (evt.Level >= LogEventLevel.Warning) + { + return true; + } + + // For Information level, only log from allowed sources + if (evt.Level == LogEventLevel.Information && evt.Properties.ContainsKey(SourceContextKey)) + { + var sourceContext = evt.Properties[SourceContextKey].ToString().Trim('"'); + if (AllowedInformationSourcesForDatabase.Contains(sourceContext)) + { + return true; + } + } + + return false; + } + /// /// Helper method to create the source context filter. /// @@ -76,8 +133,8 @@ public static class LoggingConfiguration { return evt => { - var sourceContext = evt.Properties.ContainsKey("SourceContext") - ? evt.Properties["SourceContext"].ToString() + var sourceContext = evt.Properties.ContainsKey(SourceContextKey) + ? evt.Properties[SourceContextKey].ToString() : string.Empty; var configuredLevel = GetLogEventLevel(sourceContext, configuration); return evt.Level >= configuredLevel;