diff --git a/changelog.d/1328-error-message-logs.security.md b/changelog.d/1328-error-message-logs.security.md new file mode 100644 index 000000000..cd189c58f --- /dev/null +++ b/changelog.d/1328-error-message-logs.security.md @@ -0,0 +1 @@ +- **EF Core, Marten and GraphQL no longer log the free-text EncinaError.Message** (#1328). `Encina.EntityFrameworkCore`, `Encina.Marten` and `Encina.GraphQL` previously interpolated `error.Message` into structured log message templates and activity tags, risking personal data leaks in systems that carry sensitive content in error messages. The fix replaces all 5 call sites (`TransactionPipelineBehavior`, `DomainEventDispatcherInterceptor`, `EventPublishingPipelineBehavior`, `GraphQLMediatorBridge` for both query and mutation handlers, and `InlineProjectionRelay`) with `error.GetEncinaCode()`, so only the error code (or exception type) reaches the logs. Log message templates were renamed from `{ErrorMessage}` to `{ErrorCode}` accordingly. diff --git a/docs/knowledge/issues/1328.md b/docs/knowledge/issues/1328.md new file mode 100644 index 000000000..7771635bb --- /dev/null +++ b/docs/knowledge/issues/1328.md @@ -0,0 +1,96 @@ +--- +schema: 1 +nav_exclude: true +issue: 1328 +title: "[BUG] EF Core, Marten and GraphQL log EncinaError.Message through their Log.cs templates" +closed: 2026-09-26 +state_reason: completed +outcome: delivered +type: bug +area: security-compliance +review: verified +packages: +prs: + - "1397" +linked_prs: + - 1397 +knowledge: + - kind: decision + statement: "EncinaError.Message (which may carry personal or sensitive data from the business domain) NEVER reaches logs, activity tags, health-check results or plaintext storage in Encina.EntityFrameworkCore, Encina.Marten or Encina.GraphQL; only the error code or exception type does. All 5 call sites (TransactionPipelineBehavior.cs, DomainEventDispatcherInterceptor.cs, EventPublishingPipelineBehavior.cs, GraphQLMediatorBridge.cs for query and mutation, InlineProjectionRelay.cs) now use error.GetEncinaCode() instead of error.Message interpolation." + current: yes + sources: + - "paraphrase: EF Core, Marten and GraphQL were logging free-text error messages that could contain personal data; the fix replaces all message interpolations with error codes across 5 call sites (issue #1328, 2026-09-26)" + destinations: + - kind: executable-rule + status: done + target: "src/Encina.EntityFrameworkCore/Log.cs" + - kind: executable-rule + status: done + target: "src/Encina.EntityFrameworkCore/TransactionPipelineBehavior.cs" + - kind: executable-rule + status: done + target: "src/Encina.EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptor.cs" + - kind: executable-rule + status: done + target: "src/Encina.Marten/Log.cs" + - kind: executable-rule + status: done + target: "src/Encina.Marten/EventPublishingPipelineBehavior.cs" + - kind: executable-rule + status: done + target: "src/Encina.Marten/Projections/InlineProjectionRelay.cs" + - kind: executable-rule + status: done + target: "src/Encina.GraphQL/Log.cs" + - kind: executable-rule + status: done + target: "src/Encina.GraphQL/GraphQLMediatorBridge.cs" + - kind: decision + statement: "Log message templates in Encina.EntityFrameworkCore.Log, Encina.Marten.Log, Encina.Marten.ProjectionLog and Encina.GraphQL.Log that previously used {ErrorMessage} placeholder are renamed to {ErrorCode} to reflect that only the error code is now logged, not the message text." + current: yes + sources: + - "paraphrase: LoggerMessage template parameter names were updated from ErrorMessage to ErrorCode to match the fix across all package logs (issue #1328, 2026-09-26)" + destinations: + - kind: executable-rule + status: done + target: "src/Encina.EntityFrameworkCore/Log.cs" + - kind: executable-rule + status: done + target: "src/Encina.Marten/Log.cs" + - kind: executable-rule + status: done + target: "src/Encina.Marten/Projections/ProjectionLog.cs" + - kind: executable-rule + status: done + target: "src/Encina.GraphQL/Log.cs" +audit: + checklist: 1 + date: 2026-09-26 + verdict: not-audited + record: "not written yet (see #1379)" +remediation: +--- + +## Asked + +EF Core, Marten and GraphQL packages were logging the free-text `EncinaError.Message` through their `Log.cs` structured logging templates, risking exposure of sensitive or personal data that the business domain may embed in error messages. + +## Outcome + +Delivered: all 5 call sites across the three packages now use `error.GetEncinaCode()` instead of interpolating `error.Message`. LoggerMessage templates were renamed from `{ErrorMessage}` to `{ErrorCode}`. Related issues #1319 (core error message leak) and #1322 (Hangfire/Quartz adapter leaks) track the same defect class in other packages. + +## Where the knowledge lives + +- `src/Encina.EntityFrameworkCore/Log.cs` — structured logging methods with sanitized error codes. +- `src/Encina.EntityFrameworkCore/TransactionPipelineBehavior.cs` — error handling with error code only. +- `src/Encina.EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptor.cs` — error code propagation. +- `src/Encina.Marten/Log.cs` — Marten-specific logging with error codes. +- `src/Encina.Marten/EventPublishingPipelineBehavior.cs` — event publishing error handling. +- `src/Encina.Marten/Projections/InlineProjectionRelay.cs` — inline projection error handling. +- `src/Encina.GraphQL/Log.cs` — GraphQL logging with sanitized error codes. +- `src/Encina.GraphQL/GraphQLMediatorBridge.cs` — query and mutation error handling. +- Unit tests under `tests/Encina.UnitTests/` covering the affected areas. + +## Audit + +Not audited (see #1379). diff --git a/src/Encina.EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptor.cs b/src/Encina.EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptor.cs index be4d24e95..34cc1164d 100644 --- a/src/Encina.EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptor.cs +++ b/src/Encina.EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptor.cs @@ -255,86 +255,130 @@ private async Task DispatchDomainEventsAsync( foreach (var domainEvent in events) { - // Check if event implements INotification - if (domainEvent is not INotification notification) + if (!TryResolveNotification(domainEvent, out var notification)) { - if (_options.RequireINotification) - { - Log.DomainEventNotNotification( - _logger, - domainEvent.GetType().FullName ?? domainEvent.GetType().Name); - continue; - } - - // Skip non-INotification events if not required - Log.SkippingNonNotificationEvent( - _logger, - domainEvent.GetType().FullName ?? domainEvent.GetType().Name); continue; } - try - { - var publishResult = await encina.Publish(notification, cancellationToken) - .ConfigureAwait(false); + await DispatchSingleEventAsync(encina, notification, domainEvent, cancellationToken) + .ConfigureAwait(false); + } - publishResult.Match( - Right: _ => Log.DomainEventPublished( - _logger, - domainEvent.GetType().Name, - domainEvent.EventId), - Left: error => - { - Log.DomainEventPublishFailed( - _logger, - domainEvent.GetType().Name, - domainEvent.EventId, - error.Message); - - if (_options.StopOnFirstError) - { - // ROP boundary: ISaveChangesInterceptor requires exception-based error propagation. - throw new DomainEventDispatchException( - $"Failed to dispatch domain event {domainEvent.GetType().Name}: {error.Message}", - domainEvent, - error); - } - }); - } - catch (DomainEventDispatchException) - { - // Re-throw our own exception - throw; - } - catch (Exception ex) - { - Log.DomainEventPublishException( + ClearEntities(entitiesToClear); + + Log.DomainEventsDispatchCompleted(_logger, events.Count); + } + + /// + /// Resolves to an that can be + /// published, logging and skipping it when it cannot (per ). + /// + private bool TryResolveNotification(IDomainEvent domainEvent, out INotification notification) + { + if (domainEvent is INotification resolved) + { + notification = resolved; + return true; + } + + var eventTypeName = domainEvent.GetType().FullName ?? domainEvent.GetType().Name; + if (_options.RequireINotification) + { + Log.DomainEventNotNotification(_logger, eventTypeName); + } + else + { + Log.SkippingNonNotificationEvent(_logger, eventTypeName); + } + + notification = null!; + return false; + } + + /// + /// Publishes a single domain event, logging only the error code (never + /// ) on failure, and turns a failed publish or an exception + /// into a when + /// is set. + /// + private async Task DispatchSingleEventAsync( + IEncina encina, + INotification notification, + IDomainEvent domainEvent, + CancellationToken cancellationToken) + { + try + { + var publishResult = await encina.Publish(notification, cancellationToken) + .ConfigureAwait(false); + + publishResult.Match( + Right: _ => Log.DomainEventPublished( _logger, - ex, domainEvent.GetType().Name, - domainEvent.EventId); - - if (_options.StopOnFirstError) - { - // ROP boundary: ISaveChangesInterceptor requires exception-based error propagation. - throw new DomainEventDispatchException( - $"Exception while dispatching domain event {domainEvent.GetType().Name}", - domainEvent, - ex); - } - } + domainEvent.EventId), + Left: error => HandlePublishFailure(domainEvent, error)); } - - // Clear events from entities after dispatching - if (entitiesToClear is not null) + catch (DomainEventDispatchException) + { + // Re-throw our own exception + throw; + } + catch (Exception ex) { - foreach (var entity in entitiesToClear) + Log.DomainEventPublishException( + _logger, + ex, + domainEvent.GetType().Name, + domainEvent.EventId); + + if (_options.StopOnFirstError) { - entity.ClearDomainEvents(); + // ROP boundary: ISaveChangesInterceptor requires exception-based error propagation. + throw new DomainEventDispatchException( + $"Exception while dispatching domain event {domainEvent.GetType().Name}", + domainEvent, + ex); } } + } - Log.DomainEventsDispatchCompleted(_logger, events.Count); + /// + /// Logs the failed publish and, when configured to stop on the first error, throws to + /// propagate the failure through the boundary. + /// + private void HandlePublishFailure(IDomainEvent domainEvent, EncinaError error) + { + Log.DomainEventPublishFailed( + _logger, + domainEvent.GetType().Name, + domainEvent.EventId, + error.GetEncinaCode()); + + if (_options.StopOnFirstError) + { + // ROP boundary: ISaveChangesInterceptor requires exception-based error propagation. + throw new DomainEventDispatchException( + $"Failed to dispatch domain event {domainEvent.GetType().Name}: {error.Message}", + domainEvent, + error); + } + } + + /// + /// Clears dispatched events from the given entities, if any. + /// + private static void ClearEntities(List? entitiesToClear) + { + if (entitiesToClear is null) + { + return; + } + + foreach (var entity in entitiesToClear) + { + entity.ClearDomainEvents(); + } } } diff --git a/src/Encina.EntityFrameworkCore/Log.cs b/src/Encina.EntityFrameworkCore/Log.cs index 62a57d82f..bf2826d3f 100644 --- a/src/Encina.EntityFrameworkCore/Log.cs +++ b/src/Encina.EntityFrameworkCore/Log.cs @@ -23,8 +23,8 @@ internal static partial class Log [LoggerMessage(EventId = 3014, Level = LogLevel.Debug, Message = "Committing transaction for request {RequestType} (CorrelationId: {CorrelationId})")] public static partial void CommittingTransaction(ILogger logger, string requestType, string correlationId); - [LoggerMessage(EventId = 3015, Level = LogLevel.Warning, Message = "Rolling back transaction for request {RequestType} due to error: {ErrorMessage} (CorrelationId: {CorrelationId})")] - public static partial void RollingBackTransactionDueToError(ILogger logger, string requestType, string errorMessage, string correlationId); + [LoggerMessage(EventId = 3015, Level = LogLevel.Warning, Message = "Rolling back transaction for request {RequestType} due to error: {ErrorCode} (CorrelationId: {CorrelationId})")] + public static partial void RollingBackTransactionDueToError(ILogger logger, string requestType, string errorCode, string correlationId); [LoggerMessage(EventId = 3016, Level = LogLevel.Error, Message = "Rolling back transaction for request {RequestType} due to exception (CorrelationId: {CorrelationId})")] public static partial void RollingBackTransactionDueToException(ILogger logger, Exception exception, string requestType, string correlationId); @@ -55,8 +55,8 @@ internal static partial class Log [LoggerMessage(EventId = 3024, Level = LogLevel.Information, Message = "Stored {Count} notifications in outbox (CorrelationId: {CorrelationId})")] public static partial void StoredNotificationsInOutbox(ILogger logger, int count, string correlationId); - [LoggerMessage(EventId = 3025, Level = LogLevel.Debug, Message = "Skipping outbox storage for {Count} notifications due to error: {ErrorMessage} (CorrelationId: {CorrelationId})")] - public static partial void SkippingOutboxStorageDueToError(ILogger logger, int count, string errorMessage, string correlationId); + [LoggerMessage(EventId = 3025, Level = LogLevel.Debug, Message = "Skipping outbox storage for {Count} notifications due to error: {ErrorCode} (CorrelationId: {CorrelationId})")] + public static partial void SkippingOutboxStorageDueToError(ILogger logger, int count, string errorCode, string correlationId); // Outbox Processor: EventIds 3026-3034 were retired when the EF Core processor moved onto // Encina.Messaging.Outbox.OutboxProcessorBase, which logs through MessagingLog (2827-2833, 2958). @@ -90,8 +90,8 @@ internal static partial class Log [LoggerMessage(EventId = 3043, Level = LogLevel.Debug, Message = "Skipping non-INotification domain event {EventType}")] public static partial void SkippingNonNotificationEvent(ILogger logger, string eventType); - [LoggerMessage(EventId = 3044, Level = LogLevel.Warning, Message = "Failed to publish domain event {EventType} (EventId: {EventId}): {ErrorMessage}")] - public static partial void DomainEventPublishFailed(ILogger logger, string eventType, Guid eventId, string errorMessage); + [LoggerMessage(EventId = 3044, Level = LogLevel.Warning, Message = "Failed to publish domain event {EventType} (EventId: {EventId}): {ErrorCode}")] + public static partial void DomainEventPublishFailed(ILogger logger, string eventType, Guid eventId, string errorCode); [LoggerMessage(EventId = 3045, Level = LogLevel.Error, Message = "Exception while publishing domain event {EventType} (EventId: {EventId})")] public static partial void DomainEventPublishException(ILogger logger, Exception exception, string eventType, Guid eventId); diff --git a/src/Encina.EntityFrameworkCore/TransactionPipelineBehavior.cs b/src/Encina.EntityFrameworkCore/TransactionPipelineBehavior.cs index 2c0328dd3..c45ae7518 100644 --- a/src/Encina.EntityFrameworkCore/TransactionPipelineBehavior.cs +++ b/src/Encina.EntityFrameworkCore/TransactionPipelineBehavior.cs @@ -80,7 +80,9 @@ public async ValueTask> Handle( // Check if request requires transaction if (!RequiresTransaction(request)) + { return await nextStep(); + } // Check if already in transaction (nested transaction scenario) if (_dbContext.Database.CurrentTransaction != null) @@ -90,6 +92,19 @@ public async ValueTask> Handle( return await nextStep(); } + return await ExecuteInNewTransactionAsync(context, nextStep, cancellationToken) + .ConfigureAwait(false); + } + + /// + /// Begins a new database transaction, runs the pipeline inside it, and commits or rolls + /// back based on the outcome (or on an exception). + /// + private async ValueTask> ExecuteInNewTransactionAsync( + IRequestContext context, + RequestHandlerCallback nextStep, + CancellationToken cancellationToken) + { // Get isolation level from attribute or use default var isolationLevel = GetIsolationLevel(); @@ -108,26 +123,14 @@ public async ValueTask> Handle( var result = await nextStep(); // Commit or rollback based on result - await result.Match( - Right: async _ => - { - Log.CommittingTransaction(_logger, typeof(TRequest).Name, context.CorrelationId); - - await transaction.CommitAsync(cancellationToken); - }, - Left: async error => - { - Log.RollingBackTransactionDueToError(_logger, typeof(TRequest).Name, error.Message, context.CorrelationId); - - await transaction.RollbackAsync(cancellationToken); - }); + await CommitOrRollbackAsync(transaction, result, context, cancellationToken) + .ConfigureAwait(false); return result; } catch (OperationCanceledException) { - if (transaction != null) - await transaction.RollbackAsync(cancellationToken); + await RollbackIfActiveAsync(transaction, cancellationToken).ConfigureAwait(false); throw; } @@ -135,8 +138,7 @@ await result.Match( { Log.RollingBackTransactionDueToException(_logger, ex, typeof(TRequest).Name, context.CorrelationId); - if (transaction != null) - await transaction.RollbackAsync(cancellationToken); + await RollbackIfActiveAsync(transaction, cancellationToken).ConfigureAwait(false); return EncinaErrors.FromException("transaction.failed", ex); } @@ -146,6 +148,44 @@ await result.Match( } } + /// + /// Commits the transaction when the pipeline succeeded, or rolls it back and logs only the + /// error code (never ) when it failed. + /// + private async ValueTask CommitOrRollbackAsync( + IDbContextTransaction transaction, + Either result, + IRequestContext context, + CancellationToken cancellationToken) + { + await result.Match( + Right: async _ => + { + Log.CommittingTransaction(_logger, typeof(TRequest).Name, context.CorrelationId); + + await transaction.CommitAsync(cancellationToken); + }, + Left: async error => + { + Log.RollingBackTransactionDueToError(_logger, typeof(TRequest).Name, error.GetEncinaCode(), context.CorrelationId); + + await transaction.RollbackAsync(cancellationToken); + }); + } + + /// + /// Rolls back the transaction if one was successfully started before the failure. + /// + private static async ValueTask RollbackIfActiveAsync( + IDbContextTransaction? transaction, + CancellationToken cancellationToken) + { + if (transaction != null) + { + await transaction.RollbackAsync(cancellationToken); + } + } + private static bool RequiresTransaction(TRequest request) { // Check for marker interface diff --git a/src/Encina.GraphQL/GraphQLMediatorBridge.cs b/src/Encina.GraphQL/GraphQLMediatorBridge.cs index 23522348b..bebfff4b2 100644 --- a/src/Encina.GraphQL/GraphQLMediatorBridge.cs +++ b/src/Encina.GraphQL/GraphQLMediatorBridge.cs @@ -55,7 +55,7 @@ public async ValueTask> QueryAsync result.IfRight(_ => Log.SuccessfullyExecutedQuery(_logger, typeof(TQuery).Name)); - result.IfLeft(error => Log.QueryFailed(_logger, typeof(TQuery).Name, error.Message)); + result.IfLeft(error => Log.QueryFailed(_logger, typeof(TQuery).Name, error.GetEncinaCode())); return result; } @@ -97,7 +97,7 @@ public async ValueTask> MutateAsync Log.SuccessfullyExecutedMutation(_logger, typeof(TMutation).Name)); - result.IfLeft(error => Log.MutationFailed(_logger, typeof(TMutation).Name, error.Message)); + result.IfLeft(error => Log.MutationFailed(_logger, typeof(TMutation).Name, error.GetEncinaCode())); return result; } diff --git a/src/Encina.GraphQL/Log.cs b/src/Encina.GraphQL/Log.cs index 1ba9349a1..92efe33e7 100644 --- a/src/Encina.GraphQL/Log.cs +++ b/src/Encina.GraphQL/Log.cs @@ -13,8 +13,8 @@ internal static partial class Log [LoggerMessage(EventId = 4551, Level = LogLevel.Debug, Message = "Successfully executed GraphQL query of type {QueryType}")] public static partial void SuccessfullyExecutedQuery(ILogger logger, string queryType); - [LoggerMessage(EventId = 4552, Level = LogLevel.Warning, Message = "GraphQL query of type {QueryType} failed: {ErrorMessage}")] - public static partial void QueryFailed(ILogger logger, string queryType, string errorMessage); + [LoggerMessage(EventId = 4552, Level = LogLevel.Warning, Message = "GraphQL query of type {QueryType} failed: {ErrorCode}")] + public static partial void QueryFailed(ILogger logger, string queryType, string errorCode); [LoggerMessage(EventId = 4553, Level = LogLevel.Error, Message = "Failed to execute GraphQL query of type {QueryType}")] public static partial void FailedToExecuteQuery(ILogger logger, Exception exception, string queryType); @@ -25,8 +25,8 @@ internal static partial class Log [LoggerMessage(EventId = 4555, Level = LogLevel.Debug, Message = "Successfully executed GraphQL mutation of type {MutationType}")] public static partial void SuccessfullyExecutedMutation(ILogger logger, string mutationType); - [LoggerMessage(EventId = 4556, Level = LogLevel.Warning, Message = "GraphQL mutation of type {MutationType} failed: {ErrorMessage}")] - public static partial void MutationFailed(ILogger logger, string mutationType, string errorMessage); + [LoggerMessage(EventId = 4556, Level = LogLevel.Warning, Message = "GraphQL mutation of type {MutationType} failed: {ErrorCode}")] + public static partial void MutationFailed(ILogger logger, string mutationType, string errorCode); [LoggerMessage(EventId = 4557, Level = LogLevel.Error, Message = "Failed to execute GraphQL mutation of type {MutationType}")] public static partial void FailedToExecuteMutation(ILogger logger, Exception exception, string mutationType); diff --git a/src/Encina.Marten/EventPublishingPipelineBehavior.cs b/src/Encina.Marten/EventPublishingPipelineBehavior.cs index 5f07cfaf1..c22fe1536 100644 --- a/src/Encina.Marten/EventPublishingPipelineBehavior.cs +++ b/src/Encina.Marten/EventPublishingPipelineBehavior.cs @@ -59,42 +59,73 @@ public async ValueTask> Handle( return result; } - // Get pending events from the session - var pendingEvents = _session.PendingChanges.Streams() - .SelectMany(s => s.Events) - .Select(e => e.Data) - .OfType() - .ToList(); - + var pendingEvents = GetPendingNotifications(); if (pendingEvents.Count == 0) { return result; } + var publishError = await PublishPendingEventsAsync(pendingEvents, cancellationToken) + .ConfigureAwait(false); + + // NOSONAR S6966: LanguageExt Left is a pure function + return publishError is { } error ? Left(error) : result; + } + + /// + /// Gets the pending domain-event notifications recorded on the session since the last save. + /// + private List GetPendingNotifications() => + _session.PendingChanges.Streams() + .SelectMany(s => s.Events) + .Select(e => e.Data) + .OfType() + .ToList(); + + /// + /// Publishes every pending domain event in order, stopping at the first failure. + /// + /// when every event published; otherwise the first failure. + private async ValueTask PublishPendingEventsAsync( + List pendingEvents, CancellationToken cancellationToken) + { Log.PublishingDomainEvents(_logger, pendingEvents.Count, typeof(TRequest).Name); - // Publish each domain event foreach (var domainEvent in pendingEvents) { - var publishResult = await _encina.Publish(domainEvent, cancellationToken).ConfigureAwait(false); - - if (publishResult.IsLeft) + var publishError = await PublishEventAsync(domainEvent, cancellationToken).ConfigureAwait(false); + if (publishError is not null) { - var error = publishResult.Match( - Left: err => err, - Right: _ => EncinaErrors.Unknown); - - Log.FailedToPublishDomainEvent(_logger, domainEvent.GetType().Name, error.Message); - - return Left( // NOSONAR S6966: LanguageExt Left is a pure function - EncinaErrors.Create( - MartenErrorCodes.PublishEventsFailed, - $"Failed to publish domain event {domainEvent.GetType().Name}: {error.Message}")); + return publishError; } } Log.PublishedDomainEvents(_logger, pendingEvents.Count, typeof(TRequest).Name); - return result; + return null; + } + + /// + /// Publishes a single domain event and, on failure, logs only the error code (never + /// ) and returns the wrapped error to report upstream. + /// + /// when the publish succeeded; otherwise the error to return. + private async ValueTask PublishEventAsync(INotification domainEvent, CancellationToken cancellationToken) + { + var publishResult = await _encina.Publish(domainEvent, cancellationToken).ConfigureAwait(false); + if (publishResult.IsRight) + { + return null; + } + + var error = publishResult.Match( + Left: err => err, + Right: _ => EncinaErrors.Unknown); + + Log.FailedToPublishDomainEvent(_logger, domainEvent.GetType().Name, error.GetEncinaCode()); + + return EncinaErrors.Create( + MartenErrorCodes.PublishEventsFailed, + $"Failed to publish domain event {domainEvent.GetType().Name}: {error.Message}"); } } diff --git a/src/Encina.Marten/Log.cs b/src/Encina.Marten/Log.cs index 017dcbc76..eb915b8f7 100644 --- a/src/Encina.Marten/Log.cs +++ b/src/Encina.Marten/Log.cs @@ -57,8 +57,8 @@ internal static partial class Log [LoggerMessage(EventId = 2614, Level = LogLevel.Debug, Message = "Publishing {EventCount} domain events after command {CommandType}")] public static partial void PublishingDomainEvents(ILogger logger, int eventCount, string commandType); - [LoggerMessage(EventId = 2615, Level = LogLevel.Error, Message = "Failed to publish domain event {EventType}: {ErrorMessage}")] - public static partial void FailedToPublishDomainEvent(ILogger logger, string eventType, string errorMessage); + [LoggerMessage(EventId = 2615, Level = LogLevel.Error, Message = "Failed to publish domain event {EventType}: {ErrorCode}")] + public static partial void FailedToPublishDomainEvent(ILogger logger, string eventType, string errorCode); [LoggerMessage(EventId = 2616, Level = LogLevel.Information, Message = "Successfully published {EventCount} domain events after command {CommandType}")] public static partial void PublishedDomainEvents(ILogger logger, int eventCount, string commandType); diff --git a/src/Encina.Marten/Projections/InlineProjectionRelay.cs b/src/Encina.Marten/Projections/InlineProjectionRelay.cs index 2054ecd6e..d749ea80f 100644 --- a/src/Encina.Marten/Projections/InlineProjectionRelay.cs +++ b/src/Encina.Marten/Projections/InlineProjectionRelay.cs @@ -131,10 +131,10 @@ public async Task> ProjectAsync( return result; } - var errorMessage = result.Match( + var errorCode = result.Match( Right: static _ => string.Empty, - Left: static error => error.Message); - ProjectionLog.InlineProjectionFailedAfterSave(_logger, aggregateType, streamId, errorMessage); + Left: static error => error.GetEncinaCode()); + ProjectionLog.InlineProjectionFailedAfterSave(_logger, aggregateType, streamId, errorCode); return Right(Unit.Default); // NOSONAR S6966: LanguageExt Right is a pure function } diff --git a/src/Encina.Marten/Projections/ProjectionLog.cs b/src/Encina.Marten/Projections/ProjectionLog.cs index f5312d45d..5ba7111cd 100644 --- a/src/Encina.Marten/Projections/ProjectionLog.cs +++ b/src/Encina.Marten/Projections/ProjectionLog.cs @@ -344,10 +344,10 @@ public static partial void NoHandlerForEvent( [LoggerMessage( EventId = 2700, Level = LogLevel.Warning, - Message = "Inline projections failed for aggregate {AggregateType} with ID {Id} after its events were saved; read models may be stale: {ErrorMessage}")] + Message = "Inline projections failed for aggregate {AggregateType} with ID {Id} after its events were saved; read models may be stale: {ErrorCode}")] public static partial void InlineProjectionFailedAfterSave( ILogger logger, string aggregateType, Guid id, - string errorMessage); + string errorCode); } diff --git a/src/Encina/Encina.csproj b/src/Encina/Encina.csproj index 113b6af7b..1300c81e7 100644 --- a/src/Encina/Encina.csproj +++ b/src/Encina/Encina.csproj @@ -64,6 +64,12 @@ <_Parameter1>Encina.MongoDB + + <_Parameter1>Encina.Marten + + + <_Parameter1>Encina.GraphQL + <_Parameter1>DynamicProxyGenAssembly2 diff --git a/tests/Encina.UnitTests/EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptorTests.cs b/tests/Encina.UnitTests/EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptorTests.cs index 22d4db9a0..2d0f41847 100644 --- a/tests/Encina.UnitTests/EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptorTests.cs +++ b/tests/Encina.UnitTests/EntityFrameworkCore/DomainEvents/DomainEventDispatcherInterceptorTests.cs @@ -7,6 +7,7 @@ using Microsoft.EntityFrameworkCore.Diagnostics; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; using NSubstitute; namespace Encina.UnitTests.EntityFrameworkCore.DomainEvents; @@ -438,6 +439,50 @@ public async Task SavedChangesAsync_DontStopOnFirstError_ShouldContinue() await encina.Received(2).Publish(Arg.Any(), Arg.Any()); } + [Fact] + public async Task SavedChangesAsync_PublishFails_LogsOnlyTheErrorCodeNotTheMessage() + { + // Arrange - a distinctive sentinel stands in for data that must never leave the process + // through structured logs (AGENTS.md #3: EncinaError.Message never reaches logs; #1328). + const string sentinel = "SENTINEL-do-not-log-4f2a"; + var error = EncinaErrors.Create("test.publish.error", $"Publish failed: {sentinel}"); + var encina = Substitute.For(); + encina.Publish(Arg.Any(), Arg.Any()) + .Returns(new ValueTask>(error)); + + var services = new ServiceCollection(); + services.AddSingleton(encina); + var serviceProvider = services.BuildServiceProvider(); + + var options = new DomainEventDispatcherOptions + { + Enabled = true, + StopOnFirstError = false + }; + var logger = new FakeLogger(); + var interceptor = new DomainEventDispatcherInterceptor(serviceProvider, options, logger); + + var dbOptions = new DbContextOptionsBuilder() + .UseInMemoryDatabase(Guid.NewGuid().ToString()) + .AddInterceptors(interceptor) + .Options; + + await using var context = new TestDbContext(dbOptions); + + var aggregate = new TestAggregate(); + aggregate.RaiseEvent(new TestNotificationEvent(aggregate.Id)); + + context.TestAggregates.Add(aggregate); + + // Act + await context.SaveChangesAsync(); + + // Assert + var logs = logger.Collector.GetSnapshot(); + logs.ShouldContain(r => r.Message.Contains("test.publish.error")); + logs.ShouldAllBe(r => !r.Message.Contains(sentinel)); + } + #endregion #region Pre-Save Event Collection Tests (CollectEventsBeforeSave Option) diff --git a/tests/Encina.UnitTests/EntityFrameworkCore/TransactionPipelineBehaviorIntegrationTests.cs b/tests/Encina.UnitTests/EntityFrameworkCore/TransactionPipelineBehaviorIntegrationTests.cs index 3ecc932a8..fc3508ff2 100644 --- a/tests/Encina.UnitTests/EntityFrameworkCore/TransactionPipelineBehaviorIntegrationTests.cs +++ b/tests/Encina.UnitTests/EntityFrameworkCore/TransactionPipelineBehaviorIntegrationTests.cs @@ -5,6 +5,7 @@ using Microsoft.EntityFrameworkCore; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Testing; using NSubstitute; using Shouldly; using Xunit; @@ -306,6 +307,31 @@ public async Task Handle_ExceptionInPipeline_RollsBackAndReturnsLeft() _dbContext.Database.CurrentTransaction.ShouldBeNull(); } + [Fact] + public async Task Handle_FailureResult_LogsOnlyTheErrorCodeNotTheMessage() + { + // Arrange - a distinctive sentinel stands in for data that must never leave the process + // through structured logs (AGENTS.md #3: EncinaError.Message never reaches logs; #1328). + const string sentinel = "SENTINEL-do-not-log-4f2a"; + var error = EncinaErrors.Create("test.rollback.error", $"Rollback failed: {sentinel}"); + var logger = new FakeLogger>(); + var behavior = new TransactionPipelineBehavior(_dbContext, logger); + var command = new TestTransactionalCommand(); + + // Act + var result = await behavior.Handle( + command, + _context, + () => ValueTask.FromResult(Either.Left(error)), + CancellationToken.None); + + // Assert + result.IsLeft.ShouldBeTrue(); + var logs = logger.Collector.GetSnapshot(); + logs.ShouldContain(r => r.Message.Contains("test.rollback.error")); + logs.ShouldAllBe(r => !r.Message.Contains(sentinel)); + } + #endregion public void Dispose() diff --git a/tests/Encina.UnitTests/GraphQL/GraphQLEncinaBridgeTests.cs b/tests/Encina.UnitTests/GraphQL/GraphQLEncinaBridgeTests.cs index 6e7496207..79fc77f9a 100644 --- a/tests/Encina.UnitTests/GraphQL/GraphQLEncinaBridgeTests.cs +++ b/tests/Encina.UnitTests/GraphQL/GraphQLEncinaBridgeTests.cs @@ -1,6 +1,7 @@ using Encina.GraphQL; using LanguageExt; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Testing; using static LanguageExt.Prelude; namespace Encina.UnitTests.GraphQL; @@ -89,6 +90,29 @@ public async Task QueryAsync_EncinaThrows_ShouldReturnLeft() result.IsLeft.ShouldBeTrue(); } + [Fact] + public async Task QueryAsync_EncinaReturnsError_LogsOnlyTheErrorCodeNotTheMessage() + { + // Arrange - a distinctive sentinel stands in for data that must never leave the process + // through structured logs (AGENTS.md #3: EncinaError.Message never reaches logs; #1328). + const string sentinel = "SENTINEL-do-not-log-4f2a"; + var error = EncinaErrors.Create("test.query.error", $"Query failed: {sentinel}"); + _encina.Send(Arg.Any(), Arg.Any()) + .Returns(Left(error)); + + var logger = new FakeLogger(); + var bridge = new GraphQLEncinaBridge(_encina, logger, Options.Create(_options)); + + // Act + var result = await bridge.QueryAsync(new TestQuery()); + + // Assert + result.IsLeft.ShouldBeTrue(); + var logs = logger.Collector.GetSnapshot(); + logs.ShouldContain(r => r.Message.Contains("test.query.error")); + logs.ShouldAllBe(r => !r.Message.Contains(sentinel)); + } + #endregion #region MutateAsync @@ -126,6 +150,29 @@ public async Task MutateAsync_EncinaThrows_ShouldReturnLeft() result.IsLeft.ShouldBeTrue(); } + [Fact] + public async Task MutateAsync_EncinaReturnsError_LogsOnlyTheErrorCodeNotTheMessage() + { + // Arrange - a distinctive sentinel stands in for data that must never leave the process + // through structured logs (AGENTS.md #3: EncinaError.Message never reaches logs; #1328). + const string sentinel = "SENTINEL-do-not-log-4f2a"; + var error = EncinaErrors.Create("test.mutation.error", $"Mutation failed: {sentinel}"); + _encina.Send(Arg.Any(), Arg.Any()) + .Returns(Left(error)); + + var logger = new FakeLogger(); + var bridge = new GraphQLEncinaBridge(_encina, logger, Options.Create(_options)); + + // Act + var result = await bridge.MutateAsync(new TestMutation()); + + // Assert + result.IsLeft.ShouldBeTrue(); + var logs = logger.Collector.GetSnapshot(); + logs.ShouldContain(r => r.Message.Contains("test.mutation.error")); + logs.ShouldAllBe(r => !r.Message.Contains(sentinel)); + } + #endregion #region SubscribeAsync diff --git a/tests/Encina.UnitTests/Marten/EventPublishingPipelineBehaviorTests.cs b/tests/Encina.UnitTests/Marten/EventPublishingPipelineBehaviorTests.cs index 0b5c3a45a..4d5b98bbc 100644 --- a/tests/Encina.UnitTests/Marten/EventPublishingPipelineBehaviorTests.cs +++ b/tests/Encina.UnitTests/Marten/EventPublishingPipelineBehaviorTests.cs @@ -1,8 +1,11 @@ +using System.Diagnostics.CodeAnalysis; using Encina.Marten; +using JasperFx.Events; using LanguageExt; using Marten; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Testing; using Microsoft.Extensions.Options; using NSubstitute; using Shouldly; @@ -10,6 +13,7 @@ namespace Encina.UnitTests.Marten; +[SuppressMessage("Reliability", "CA2012:Use ValueTasks correctly", Justification = "Mock setup pattern for NSubstitute")] public class EventPublishingPipelineBehaviorTests { private readonly IDocumentSession _session; @@ -132,6 +136,38 @@ await _encina.DidNotReceive().Publish( Arg.Any(), Arg.Any()); } + [Fact] + public async Task Handle_PublishFails_LogsOnlyTheErrorCodeNotTheMessage() + { + // Arrange - a distinctive sentinel stands in for data that must never leave the process + // through structured logs (AGENTS.md #3: EncinaError.Message never reaches logs; #1328). + const string sentinel = "SENTINEL-do-not-log-4f2a"; + var error = EncinaErrors.Create("test.publish.error", $"Publish failed: {sentinel}"); + var logger = new FakeLogger>(); + var sut = new EventPublishingPipelineBehavior( + _session, _encina, logger, _options); + + var pendingEvent = new Event(new TestNotification("hello")); + var streamAction = StreamAction.Start(Guid.NewGuid(), pendingEvent); + _session.PendingChanges.Streams().Returns([streamAction]); + + _encina.Publish(Arg.Any(), Arg.Any()) + .Returns(new ValueTask>(Left(error))); + + RequestHandlerCallback next = () => + new ValueTask>( + Right(new TestResponse())); + + // Act + var result = await sut.Handle(new TestCommand(), _requestContext, next, CancellationToken.None); + + // Assert + result.IsLeft.ShouldBeTrue(); + var logs = logger.Collector.GetSnapshot(); + logs.ShouldContain(r => r.Message.Contains("test.publish.error")); + logs.ShouldAllBe(r => !r.Message.Contains(sentinel)); + } + // Test types public sealed record TestCommand : ICommand; diff --git a/tests/Encina.UnitTests/Marten/Projections/InlineProjectionRelayTests.cs b/tests/Encina.UnitTests/Marten/Projections/InlineProjectionRelayTests.cs index 46b9b55cd..44cbfaebf 100644 --- a/tests/Encina.UnitTests/Marten/Projections/InlineProjectionRelayTests.cs +++ b/tests/Encina.UnitTests/Marten/Projections/InlineProjectionRelayTests.cs @@ -3,6 +3,7 @@ using LanguageExt; using Marten; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Testing; using NSubstitute; using NSubstitute.ExceptionExtensions; using Shouldly; @@ -171,6 +172,31 @@ public async Task ProjectAsync_DispatcherFails_ThrowOnProjectionErrorFalse_Retur result.IsRight.ShouldBeTrue(); } + [Fact] + public async Task ProjectAsync_DispatcherFails_ThrowOnProjectionErrorFalse_LogsOnlyTheErrorCodeNotTheMessage() + { + // Arrange - a distinctive sentinel stands in for data that must never leave the process + // through structured logs (AGENTS.md #3: EncinaError.Message never reaches logs; #1328). + const string sentinel = "SENTINEL-do-not-log-4f2a"; + var streamId = Guid.NewGuid(); + StreamHas(streamId, Envelope(streamId, 1, new FirstEvent())); + _options.ThrowOnProjectionError = false; + _dispatcher + .DispatchManyAsync(Arg.Any>(), Arg.Any()) + .Returns(Left(EncinaErrors.Create("test.projection.error", $"Projection failed: {sentinel}"))); + var logger = new FakeLogger(); + var sut = new InlineProjectionRelay(_session, _dispatcher, _options, logger); + + // Act + var result = await sut.ProjectAsync("Agg", streamId, 0, CancellationToken.None); + + // Assert + result.IsRight.ShouldBeTrue(); + var logs = logger.Collector.GetSnapshot(); + logs.ShouldContain(r => r.Message.Contains("test.projection.error")); + logs.ShouldAllBe(r => !r.Message.Contains(sentinel)); + } + [Fact] public async Task ProjectAsync_DispatcherFails_ThrowOnProjectionErrorTrue_ReturnsTheProjectionError() {