From 7b9b544eee431f3fc8ae0d04b3bf7b77301a8d23 Mon Sep 17 00:00:00 2001 From: Paul Welter Date: Fri, 23 Aug 2024 11:46:41 -0500 Subject: [PATCH] improve logging for hangfire and audit --- .gitignore | 1 + .../Jobs/Commands/BackgroundUpdateCommand.cs | 21 ++++ .../Jobs/Handlers/BackgroundUpdateHandler.cs | 27 ++++++ .../Domain/Jobs/JobServiceRegistration.cs | 21 ++++ .../Endpoints/JobEndpoint.cs | 59 ++++++++++++ .../Program.cs | 95 +++++++++++++++---- ...cker.WebService.EntityFrameworkCore.csproj | 5 +- .../Tracker.WebService.MongoDB.csproj | 2 +- src/Directory.Build.props | 1 + .../ChangeCollector.cs | 37 ++++++-- .../IMediatorDispatcher.cs | 3 +- .../MediatorDispatcher.cs | 13 ++- .../MediatorExtensions.cs | 2 +- .../MediatR.CommandQuery.Cosmos.Tests.csproj | 2 +- ...EntityFrameworkCore.SqlServer.Tests.csproj | 2 +- ...mandQuery.EntityFrameworkCore.Tests.csproj | 2 +- .../MediatR.CommandQuery.MongoDB.Tests.csproj | 2 +- .../MediatR.CommandQuery.Tests.csproj | 2 +- 18 files changed, 256 insertions(+), 41 deletions(-) create mode 100644 samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/Commands/BackgroundUpdateCommand.cs create mode 100644 samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/Handlers/BackgroundUpdateHandler.cs create mode 100644 samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/JobServiceRegistration.cs create mode 100644 samples/Tracker.WebService.EntityFrameworkCore/Endpoints/JobEndpoint.cs diff --git a/.gitignore b/.gitignore index d4d65026..ca0b948c 100644 --- a/.gitignore +++ b/.gitignore @@ -349,3 +349,4 @@ MigrationBackup/ *.GhostDoc.xml *.csv *.txt +*.clef \ No newline at end of file diff --git a/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/Commands/BackgroundUpdateCommand.cs b/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/Commands/BackgroundUpdateCommand.cs new file mode 100644 index 00000000..63fde680 --- /dev/null +++ b/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/Commands/BackgroundUpdateCommand.cs @@ -0,0 +1,21 @@ +using MediatR; +using MediatR.CommandQuery.Models; + +namespace Tracker.WebService.Domain.Commands; + +public class BackgroundUpdateCommand : IRequest +{ + + public BackgroundUpdateCommand(int id) + { + Id = id; + } + + public int Id { get; } + + + public override string ToString() + { + return $"Background Update {Id}"; + } +} diff --git a/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/Handlers/BackgroundUpdateHandler.cs b/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/Handlers/BackgroundUpdateHandler.cs new file mode 100644 index 00000000..652ef746 --- /dev/null +++ b/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/Handlers/BackgroundUpdateHandler.cs @@ -0,0 +1,27 @@ +using System.Threading; +using System.Threading.Tasks; + +using MediatR.CommandQuery.Handlers; +using MediatR.CommandQuery.Models; + +using Microsoft.Extensions.Logging; + +using Tracker.WebService.Domain.Commands; + +namespace Tracker.WebService.Domain.Handlers; + +public class BackgroundUpdateHandler : RequestHandlerBase +{ + public BackgroundUpdateHandler(ILoggerFactory loggerFactory) : base(loggerFactory) + { + } + + protected override async Task Process(BackgroundUpdateCommand request, CancellationToken cancellationToken) + { + Logger.LogInformation("Process Background Job: {Request}", request); + + await Task.Delay(500, cancellationToken); + + return new CompleteModel { Successful = true }; + } +} diff --git a/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/JobServiceRegistration.cs b/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/JobServiceRegistration.cs new file mode 100644 index 00000000..4466e7cf --- /dev/null +++ b/samples/Tracker.WebService.EntityFrameworkCore/Domain/Jobs/JobServiceRegistration.cs @@ -0,0 +1,21 @@ +using MediatR; +using MediatR.CommandQuery.Models; + +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; + +using Tracker.WebService.Domain.Commands; +using Tracker.WebService.Domain.Handlers; + +// ReSharper disable once CheckNamespace +namespace Tracker.WebService.Domain; + +public class JobServiceRegistration +{ + [RegisterServices] + public void Register(IServiceCollection services) + { + services.TryAddTransient, BackgroundUpdateHandler>(); + } + +} diff --git a/samples/Tracker.WebService.EntityFrameworkCore/Endpoints/JobEndpoint.cs b/samples/Tracker.WebService.EntityFrameworkCore/Endpoints/JobEndpoint.cs new file mode 100644 index 00000000..a8e7b24f --- /dev/null +++ b/samples/Tracker.WebService.EntityFrameworkCore/Endpoints/JobEndpoint.cs @@ -0,0 +1,59 @@ +using System; +using System.Security.Claims; +using System.Threading; +using System.Threading.Tasks; + +using MediatR; +using MediatR.CommandQuery.Endpoints; +using MediatR.CommandQuery.Hangfire; +using MediatR.CommandQuery.Models; + +using Microsoft.AspNetCore.Builder; +using Microsoft.AspNetCore.Http; +using Microsoft.AspNetCore.Mvc; +using Microsoft.AspNetCore.Routing; + +using Tracker.WebService.Domain.Commands; + +namespace Tracker.WebService.Endpoints; + +[RegisterTransient(Duplicate = DuplicateStrategy.Append)] +public class JobEndpoint : MediatorEndpointBase +{ + public JobEndpoint(IMediator mediator) : base(mediator) + { + EntityName = "Jobs"; + RoutePrefix = $"/api/{EntityName}"; + } + + public string EntityName { get; } + + public string RoutePrefix { get; } + + + public override void AddRoutes(IEndpointRouteBuilder app) + { + var group = app.MapGroup(RoutePrefix); + + MapGroup(group); + } + + protected virtual void MapGroup(RouteGroupBuilder group) + { + group + .MapPost("{id}", RunJob) + .WithTags(EntityName) + .WithName($"RunJob") + .WithSummary("Run job id") + .WithDescription("Run job id"); + } + + private async Task RunJob( + [FromRoute] int id, + ClaimsPrincipal? user = default, + CancellationToken cancellationToken = default) + { + var command = new BackgroundUpdateCommand(id); + await Mediator.Enqueue(command, cancellationToken); + } +} diff --git a/samples/Tracker.WebService.EntityFrameworkCore/Program.cs b/samples/Tracker.WebService.EntityFrameworkCore/Program.cs index a4f67996..d19b7788 100644 --- a/samples/Tracker.WebService.EntityFrameworkCore/Program.cs +++ b/samples/Tracker.WebService.EntityFrameworkCore/Program.cs @@ -4,13 +4,22 @@ using System.Text.Json.Serialization; using System.Threading.Tasks; +using Hangfire; +using Hangfire.SqlServer; + using MediatR.CommandQuery.Endpoints; +using MediatR.CommandQuery.Hangfire; using Microsoft.AspNetCore.Builder; +using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; using Serilog; using Serilog.Events; +using Serilog.Formatting.Compact; using Tracker.WebService.Domain; @@ -22,10 +31,6 @@ public static class Program public static async Task Main(string[] args) { - // azure home directory - var homeDirectory = Environment.GetEnvironmentVariable("HOME") ?? "."; - var logDirectory = Path.Combine(homeDirectory, "LogFiles"); - Log.Logger = new LoggerConfiguration() .MinimumLevel.Verbose() .MinimumLevel.Override("Microsoft", LogEventLevel.Information) @@ -39,23 +44,7 @@ public static async Task Main(string[] args) var builder = WebApplication.CreateBuilder(args); - builder.Host - .UseSerilog((context, services, configuration) => configuration - .ReadFrom.Configuration(context.Configuration) - .ReadFrom.Services(services) - .Enrich.FromLogContext() - .Enrich.WithProperty("ApplicationName", builder.Environment.ApplicationName) - .Enrich.WithProperty("EnvironmentName", builder.Environment.EnvironmentName) - .WriteTo.Console(outputTemplate: OutputTemplate) - .WriteTo.File( - path: $"{logDirectory}/log.txt", - rollingInterval: RollingInterval.Day, - shared: true, - flushToDiskInterval: TimeSpan.FromSeconds(1), - outputTemplate: OutputTemplate, - retainedFileCountLimit: 10 - ) - ); + ConfigureLogging(builder); ConfigureServices(builder); @@ -78,6 +67,34 @@ public static async Task Main(string[] args) } } + private static void ConfigureLogging(WebApplicationBuilder builder) + { + string logDirectory = GetLoggingPath(); + + builder.Host + .UseSerilog((context, services, configuration) => configuration + .ReadFrom.Configuration(context.Configuration) + .ReadFrom.Services(services) + .MinimumLevel.Debug() + .MinimumLevel.Override("Microsoft", LogEventLevel.Information) + .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning) + .MinimumLevel.Override("System.Net.Http.HttpClient", LogEventLevel.Debug) + .Enrich.FromLogContext() + .Enrich.WithProperty("ApplicationName", builder.Environment.ApplicationName) + .Enrich.WithProperty("EnvironmentName", builder.Environment.EnvironmentName) + .Filter.ByExcluding(logEvent => logEvent.Exception is OperationCanceledException) + .WriteTo.Console(outputTemplate: OutputTemplate) + .WriteTo.File( + formatter: new RenderedCompactJsonFormatter(), + path: $"{logDirectory}/log.clef", + shared: true, + flushToDiskInterval: TimeSpan.FromSeconds(1), + rollingInterval: RollingInterval.Day, + retainedFileCountLimit: 10 + )); + ; + } + private static void ConfigureServices(WebApplicationBuilder builder) { var services = builder.Services; @@ -98,6 +115,32 @@ private static void ConfigureServices(WebApplicationBuilder builder) options.SerializerOptions.Converters.Add(new JsonStringEnumConverter(JsonNamingPolicy.CamelCase)); options.SerializerOptions.TypeInfoResolverChain.Add(DomainJsonContext.Default); }); + + // hangfire options + services.TryAddSingleton(new SqlServerStorageOptions + { + PrepareSchemaIfNecessary = true, + EnableHeavyMigrations = true, + SqlClientFactory = Microsoft.Data.SqlClient.SqlClientFactory.Instance + }); + + services.AddHangfire((serviceProvider, globalConfiguration) => + { + var configuration = serviceProvider.GetRequiredService(); + var stroageOptions = serviceProvider.GetRequiredService(); + var connectionString = configuration.GetConnectionString("Tracker"); + + globalConfiguration + .SetDataCompatibilityLevel(CompatibilityLevel.Version_180) + .UseSimpleAssemblyNameTypeSerializer() + .UseSqlServerStorage(connectionString, stroageOptions) + .UseMediatR(); + }); + + services.AddMediatorDispatcher(); + + services.AddHangfireServer(); + } private static void ConfigureMiddleware(WebApplication app) @@ -114,6 +157,16 @@ private static void ConfigureMiddleware(WebApplication app) app.UseAuthorization(); + app.MapHangfireDashboard("/hangfire"); app.MapFeatureEndpoints(); } + + private static string GetLoggingPath() + { + // azure home directory + var homeDirectory = Environment.GetEnvironmentVariable("HOME") ?? "."; + var logDirectory = Path.Combine(homeDirectory, "LogFiles"); + + return Path.GetFullPath(logDirectory); + } } diff --git a/samples/Tracker.WebService.EntityFrameworkCore/Tracker.WebService.EntityFrameworkCore.csproj b/samples/Tracker.WebService.EntityFrameworkCore/Tracker.WebService.EntityFrameworkCore.csproj index b5c24998..008d429c 100644 --- a/samples/Tracker.WebService.EntityFrameworkCore/Tracker.WebService.EntityFrameworkCore.csproj +++ b/samples/Tracker.WebService.EntityFrameworkCore/Tracker.WebService.EntityFrameworkCore.csproj @@ -15,15 +15,18 @@ + + - + + diff --git a/samples/Tracker.WebService.MongoDB/Tracker.WebService.MongoDB.csproj b/samples/Tracker.WebService.MongoDB/Tracker.WebService.MongoDB.csproj index 34430c31..a359824f 100644 --- a/samples/Tracker.WebService.MongoDB/Tracker.WebService.MongoDB.csproj +++ b/samples/Tracker.WebService.MongoDB/Tracker.WebService.MongoDB.csproj @@ -14,7 +14,7 @@ - + diff --git a/src/Directory.Build.props b/src/Directory.Build.props index 6d9b12bf..379a7aa6 100644 --- a/src/Directory.Build.props +++ b/src/Directory.Build.props @@ -38,6 +38,7 @@ + diff --git a/src/MediatR.CommandQuery.Audit/ChangeCollector.cs b/src/MediatR.CommandQuery.Audit/ChangeCollector.cs index 590bc033..5a13f0f0 100644 --- a/src/MediatR.CommandQuery.Audit/ChangeCollector.cs +++ b/src/MediatR.CommandQuery.Audit/ChangeCollector.cs @@ -3,6 +3,8 @@ using MediatR.CommandQuery.Definitions; +using Microsoft.Extensions.Logging; + namespace MediatR.CommandQuery.Audit; /// @@ -11,18 +13,21 @@ namespace MediatR.CommandQuery.Audit; /// The type of the key. /// The type of the entity. /// -public class ChangeCollector : IChangeCollector +public partial class ChangeCollector : IChangeCollector where TEntity : IHaveIdentifier, ITrackUpdated, ITrackHistory { private readonly IEntityComparer _entityComparer; + private readonly ILogger _logger; /// /// Initializes a new instance of the class. /// /// The entity comparer. - public ChangeCollector(IEntityComparer entityComparer) + /// The logger factory. + public ChangeCollector(IEntityComparer entityComparer, ILoggerFactory loggerFactory) { _entityComparer = entityComparer; + _logger = loggerFactory.CreateLogger>(); } /// @@ -65,12 +70,23 @@ public IReadOnlyList> CollectGroupChanges(IEnumerab foreach (var group in entities.GroupBy(groupSelector)) { - var groupList = group - .OrderBy(p => p.PeriodEnd) - .ToList(); + try + { + LogCollectingChanges(_logger, entityName, group.Key); + + var groupList = group + .OrderBy(p => p.PeriodEnd) + .ToList(); - var auditList = CollectChanges(groupList, entityName, descriptionFunction); - historyList.AddRange(auditList); + var auditList = CollectChanges(groupList, entityName, descriptionFunction); + historyList.AddRange(auditList); + } + catch (Exception ex) + { + LogCollectingError(_logger, entityName, group.Key, ex.Message, ex); + + throw; + } } return historyList; @@ -160,4 +176,11 @@ public IEnumerable> CollectChanges(IEnumerable entiti return historyRecords; } + + [LoggerMessage(1, LogLevel.Debug, "Collecting changes for {EntityName} with key {EntityKey} ...")] + static partial void LogCollectingChanges(ILogger logger, string entityName, object entityKey); + + [LoggerMessage(2, LogLevel.Error, "Error collecting changes for {EntityName} with key {EntityKey}: {ErrorMessage}")] + static partial void LogCollectingError(ILogger logger, string entityName, object entityKey, string errorMessage, Exception? exception); + } diff --git a/src/MediatR.CommandQuery.Hangfire/IMediatorDispatcher.cs b/src/MediatR.CommandQuery.Hangfire/IMediatorDispatcher.cs index 56bb0c53..9c07c84a 100644 --- a/src/MediatR.CommandQuery.Hangfire/IMediatorDispatcher.cs +++ b/src/MediatR.CommandQuery.Hangfire/IMediatorDispatcher.cs @@ -1,10 +1,11 @@ using Hangfire; +using Hangfire.Server; namespace MediatR.CommandQuery.Hangfire; public interface IMediatorDispatcher { [JobDisplayName("Job: {0}")] - Task Send(TRequest request, CancellationToken cancellationToken) + Task Send(TRequest request, PerformContext? context, CancellationToken cancellationToken) where TRequest : IBaseRequest; } diff --git a/src/MediatR.CommandQuery.Hangfire/MediatorDispatcher.cs b/src/MediatR.CommandQuery.Hangfire/MediatorDispatcher.cs index 2ac52121..c39feafe 100644 --- a/src/MediatR.CommandQuery.Hangfire/MediatorDispatcher.cs +++ b/src/MediatR.CommandQuery.Hangfire/MediatorDispatcher.cs @@ -1,6 +1,7 @@ using System.Diagnostics; using Hangfire; +using Hangfire.Server; using MediatR.CommandQuery.Services; @@ -20,12 +21,14 @@ public MediatorDispatcher(IMediator mediator, ILogger logger } [JobDisplayName("Job: {0}")] - public async Task Send(TRequest request, CancellationToken cancellationToken) + public async Task Send(TRequest request, PerformContext? context, CancellationToken cancellationToken) where TRequest : IBaseRequest { if (request is null) throw new ArgumentNullException(nameof(request)); + var scope = _logger.BeginScope("Hangfire Job Id: {JobId}", context?.BackgroundJob?.Id); + var startTime = ActivityTimer.GetTimestamp(); try { @@ -46,16 +49,18 @@ public async Task Send(TRequest request, CancellationToken cancellatio { var elaspsed = ActivityTimer.GetElapsedTime(startTime); LogFinish(_logger, request, elaspsed.TotalMilliseconds); + + scope?.Dispose(); } } - [LoggerMessage(1, LogLevel.Trace, "Dispatching request '{request}' ...")] + [LoggerMessage(1, LogLevel.Trace, "Dispatching request '{Request}' ...")] static partial void LogStart(ILogger logger, IBaseRequest request); - [LoggerMessage(2, LogLevel.Trace, "Dispatched request '{request}': {elapsed} ms")] + [LoggerMessage(2, LogLevel.Trace, "Dispatched request '{Request}': {Elapsed} ms")] static partial void LogFinish(ILogger logger, IBaseRequest request, double elapsed); - [LoggerMessage(3, LogLevel.Error, "Error Dispatching request '{request}': {errorMessage}")] + [LoggerMessage(3, LogLevel.Error, "Error Dispatching request '{Request}': {ErrorMessage}")] static partial void LogError(ILogger logger, IBaseRequest request, string errorMessage, Exception? exception); } diff --git a/src/MediatR.CommandQuery.Hangfire/MediatorExtensions.cs b/src/MediatR.CommandQuery.Hangfire/MediatorExtensions.cs index f615cd17..cf3655c8 100644 --- a/src/MediatR.CommandQuery.Hangfire/MediatorExtensions.cs +++ b/src/MediatR.CommandQuery.Hangfire/MediatorExtensions.cs @@ -14,7 +14,7 @@ public static Task Enqueue(this IMediator mediator, TRequest request, throw new ArgumentNullException(nameof(request)); - BackgroundJob.Enqueue(dispatcher => dispatcher.Send(request, CancellationToken.None)); + BackgroundJob.Enqueue(dispatcher => dispatcher.Send(request, null, CancellationToken.None)); return Task.CompletedTask; } diff --git a/test/MediatR.CommandQuery.Cosmos.Tests/MediatR.CommandQuery.Cosmos.Tests.csproj b/test/MediatR.CommandQuery.Cosmos.Tests/MediatR.CommandQuery.Cosmos.Tests.csproj index ff19da4e..3c0dae08 100644 --- a/test/MediatR.CommandQuery.Cosmos.Tests/MediatR.CommandQuery.Cosmos.Tests.csproj +++ b/test/MediatR.CommandQuery.Cosmos.Tests/MediatR.CommandQuery.Cosmos.Tests.csproj @@ -14,7 +14,7 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive - + diff --git a/test/MediatR.CommandQuery.EntityFrameworkCore.SqlServer.Tests/MediatR.CommandQuery.EntityFrameworkCore.SqlServer.Tests.csproj b/test/MediatR.CommandQuery.EntityFrameworkCore.SqlServer.Tests/MediatR.CommandQuery.EntityFrameworkCore.SqlServer.Tests.csproj index 5ca837b6..0c644721 100644 --- a/test/MediatR.CommandQuery.EntityFrameworkCore.SqlServer.Tests/MediatR.CommandQuery.EntityFrameworkCore.SqlServer.Tests.csproj +++ b/test/MediatR.CommandQuery.EntityFrameworkCore.SqlServer.Tests/MediatR.CommandQuery.EntityFrameworkCore.SqlServer.Tests.csproj @@ -24,7 +24,7 @@ - + diff --git a/test/MediatR.CommandQuery.EntityFrameworkCore.Tests/MediatR.CommandQuery.EntityFrameworkCore.Tests.csproj b/test/MediatR.CommandQuery.EntityFrameworkCore.Tests/MediatR.CommandQuery.EntityFrameworkCore.Tests.csproj index 1fc529b8..80ab52ee 100644 --- a/test/MediatR.CommandQuery.EntityFrameworkCore.Tests/MediatR.CommandQuery.EntityFrameworkCore.Tests.csproj +++ b/test/MediatR.CommandQuery.EntityFrameworkCore.Tests/MediatR.CommandQuery.EntityFrameworkCore.Tests.csproj @@ -10,7 +10,7 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive - + diff --git a/test/MediatR.CommandQuery.MongoDB.Tests/MediatR.CommandQuery.MongoDB.Tests.csproj b/test/MediatR.CommandQuery.MongoDB.Tests/MediatR.CommandQuery.MongoDB.Tests.csproj index 62548696..3616b29f 100644 --- a/test/MediatR.CommandQuery.MongoDB.Tests/MediatR.CommandQuery.MongoDB.Tests.csproj +++ b/test/MediatR.CommandQuery.MongoDB.Tests/MediatR.CommandQuery.MongoDB.Tests.csproj @@ -10,7 +10,7 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive - + diff --git a/test/MediatR.CommandQuery.Tests/MediatR.CommandQuery.Tests.csproj b/test/MediatR.CommandQuery.Tests/MediatR.CommandQuery.Tests.csproj index fc3bc832..35876c2e 100644 --- a/test/MediatR.CommandQuery.Tests/MediatR.CommandQuery.Tests.csproj +++ b/test/MediatR.CommandQuery.Tests/MediatR.CommandQuery.Tests.csproj @@ -10,7 +10,7 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive - +