feat: add UnsafeEntityLogging option to guard entity serialization in logs (#446)

docs/in-depth/server/index.md

@@ -131,6 +131,7 @@ The options you can set include:
 * `MaxTop` (int, default: 512000) is the maximum number of items a user can request in a single operation.
 * `EnableSoftDelete` (bool, default: false) enables soft-delete, which marks items as deleted instead of deleting them from the database.  Soft delete allows clients to update their offline cache, but requires that deleted items are purged from the database separately.
 * `UnauthorizedStatusCode` (int, default: 401 Unauthorized) is the status code returned when the user isn't allowed to do an action.  The value must be a client error (4xx) status code in the range 400-499.
+* `UnsafeEntityLogging` (bool, default: false) controls how much entity data is written to the logs.  When `false`, only the entity ID is logged at `Information` level.  When `true`, the entity ID is logged at `Information` level and the full (serialized) entity contents are logged at `Debug` level.  Entity contents may include personally identifiable information (PII), secrets, or other sensitive business data, so only enable this option when the additional diagnostic detail is required and the log sink is appropriately secured.
 
 ## Configure access permissions
 

src/CommunityToolkit.Datasync.Server/Controllers/TableController.Create.cs

@@ -24,14 +24,23 @@ public virtual async Task<IActionResult> CreateAsync(CancellationToken cancellat
     {
         Logger.LogInformation("CreateAsync");
         TEntity entity = await DeserializeJsonContent(cancellationToken).ConfigureAwait(false);
-        Logger.LogInformation("CreateAsync: {entity}", entity.ToJsonString());
+        Logger.LogInformation("CreateAsync: {id}", entity.Id);
+        if (Options.UnsafeEntityLogging)
+        {
+            Logger.LogDebug("CreateAsync: entity {entity}", entity.ToJsonString());
+        }
 
         await AuthorizeRequestAsync(TableOperation.Create, entity, cancellationToken).ConfigureAwait(false);
         await AccessControlProvider.PreCommitHookAsync(TableOperation.Create, entity, cancellationToken).ConfigureAwait(false);
         await Repository.CreateAsync(entity, cancellationToken).ConfigureAwait(false);
         await PostCommitHookAsync(TableOperation.Create, entity, cancellationToken).ConfigureAwait(false);
 
-        Logger.LogInformation("CreateAsync: created {entity}", entity.ToJsonString());
+        Logger.LogInformation("CreateAsync: created {id}", entity.Id);
+        if (Options.UnsafeEntityLogging)
+        {
+            Logger.LogDebug("CreateAsync: created entity {entity}", entity.ToJsonString());
+        }
+
         return CreatedAtRoute(new { id = entity.Id }, entity);
     }
 }

src/CommunityToolkit.Datasync.Server/Controllers/TableController.Read.cs

@@ -42,7 +42,12 @@ public virtual async Task<IActionResult> ReadAsync([FromRoute] string id, Cancel
 
         Request.ParseConditionalRequest(entity, out _);
 
-        Logger.LogInformation("ReadAsync: read {entity}", entity.ToJsonString());
+        Logger.LogInformation("ReadAsync: read {id}", entity.Id);
+        if (Options.UnsafeEntityLogging)
+        {
+            Logger.LogDebug("ReadAsync: read entity {entity}", entity.ToJsonString());
+        }
+
         return Ok(entity);
     }
 }

src/CommunityToolkit.Datasync.Server/Controllers/TableController.Replace.cs

@@ -23,9 +23,13 @@ public partial class TableController<TEntity> : ODataController where TEntity :
     [ProducesResponseType(StatusCodes.Status200OK)]
     public virtual async Task<IActionResult> ReplaceAsync([FromRoute] string id, CancellationToken cancellationToken = default)
     {
-        Logger.LogInformation("CreateAsync");
+        Logger.LogInformation("ReplaceAsync");
         TEntity entity = await DeserializeJsonContent(cancellationToken).ConfigureAwait(false);
-        Logger.LogInformation("ReplaceAsync: {id} {entity}", id, entity.ToJsonString());
+        Logger.LogInformation("ReplaceAsync: {id}", id);
+        if (Options.UnsafeEntityLogging)
+        {
+            Logger.LogDebug("ReplaceAsync: {id} entity {entity}", id, entity.ToJsonString());
+        }
 
         if (id != entity.Id)
         {
@@ -57,7 +61,12 @@ public virtual async Task<IActionResult> ReplaceAsync([FromRoute] string id, Can
         // operation, so we have to do an additional GET to ensure we are getting the right version of the entity
         TEntity? updatedEntity = await Repository.ReadAsync(id, cancellationToken).ConfigureAwait(false);
 
-        Logger.LogInformation("ReplaceAsync: replaced {entity}", updatedEntity.ToJsonString());
+        Logger.LogInformation("ReplaceAsync: replaced {id}", updatedEntity?.Id);
+        if (Options.UnsafeEntityLogging)
+        {
+            Logger.LogDebug("ReplaceAsync: replaced entity {entity}", updatedEntity?.ToJsonString() ?? "null");
+        }
+
         return Ok(updatedEntity);
     }
 }

src/CommunityToolkit.Datasync.Server/Controllers/TableController.cs

@@ -160,7 +160,12 @@ protected virtual async ValueTask AuthorizeRequestAsync(TableOperation operation
         bool isAuthorized = await AccessControlProvider.IsAuthorizedAsync(operation, entity, cancellationToken).ConfigureAwait(false);
         if (!isAuthorized)
         {
-            Logger.LogWarning("{operation} {entity} statusCode=401 unauthorized", operation, entity?.ToJsonString() ?? "");
+            Logger.LogWarning("{operation} {id} statusCode=401 unauthorized", operation, entity?.Id ?? "");
+            if (Options.UnsafeEntityLogging)
+            {
+                Logger.LogDebug("{operation} entity {entity} statusCode=401 unauthorized", operation, entity?.ToJsonString() ?? "");
+            }
+
             throw new HttpException(Options.UnauthorizedStatusCode);
         }
     }

src/CommunityToolkit.Datasync.Server/Models/TableControllerOptions.cs

@@ -42,6 +42,19 @@ public class TableControllerOptions
     /// </summary>
     public bool EnableSoftDelete { get; set; }
 
+    /// <summary>
+    /// If <c>true</c>, then the full contents of an entity are serialized into the logs at
+    /// <c>Debug</c> level and only the entity ID is logged at <c>Information</c> level.  If
+    /// <c>false</c> (the default), only the entity ID is logged at <c>Information</c> level and
+    /// the full entity contents are never written to the logs.
+    /// </summary>
+    /// <remarks>
+    /// Entity contents may include personally identifiable information (PII), secrets, or other
+    /// sensitive business data.  Only enable this option when the additional diagnostic detail is
+    /// required and the log sink is appropriately secured.
+    /// </remarks>
+    public bool UnsafeEntityLogging { get; set; }
+
     /// <summary>
     /// The maximum page size for the results returned by a query operation.  This is the
     /// maximum value that the client can specify for the <c>$top</c> query option.

tests/CommunityToolkit.Datasync.Server.Test/Controllers/TableController_Base_Tests.cs

@@ -203,6 +203,41 @@ public async Task AuthorizeRequestAsync_AllowsIfAuthorized()
 
         await act.Should().NotThrowAsync();
     }
+
+    [Fact]
+    public async Task AuthorizeRequestAsync_UnsafeEntityLogging_False_LogsIdOnly()
+    {
+        IAccessControlProvider<TableData> provider = FakeAccessControlProvider<TableData>(TableOperation.Update, false);
+        IRepository<TableData> repository = FakeRepository<TableData>();
+        TableControllerOptions options = new() { UnsafeEntityLogging = false };
+        CapturingLogger logger = new();
+        ExposedTableController<TableData> controller = new(repository, provider, options) { Logger = logger };
+        TableData entity = new() { Id = "0da7fb24-3606-442f-9f68-c47c6e7d09d4" };
+
+        Func<Task> act = async () => await controller.__AuthorizeRequestAsync(TableOperation.Update, entity, CancellationToken.None);
+
+        (await act.Should().ThrowAsync<HttpException>()).WithStatusCode(401);
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Warning && e.Message.Contains(entity.Id));
+        logger.Entries.Should().NotContain(e => e.Message.Contains("UpdatedAt", StringComparison.OrdinalIgnoreCase));
+        logger.Entries.Should().NotContain(e => e.LogLevel == LogLevel.Debug);
+    }
+
+    [Fact]
+    public async Task AuthorizeRequestAsync_UnsafeEntityLogging_True_LogsFullEntityAtDebug()
+    {
+        IAccessControlProvider<TableData> provider = FakeAccessControlProvider<TableData>(TableOperation.Update, false);
+        IRepository<TableData> repository = FakeRepository<TableData>();
+        TableControllerOptions options = new() { UnsafeEntityLogging = true };
+        CapturingLogger logger = new();
+        ExposedTableController<TableData> controller = new(repository, provider, options) { Logger = logger };
+        TableData entity = new() { Id = "0da7fb24-3606-442f-9f68-c47c6e7d09d4" };
+
+        Func<Task> act = async () => await controller.__AuthorizeRequestAsync(TableOperation.Update, entity, CancellationToken.None);
+
+        (await act.Should().ThrowAsync<HttpException>()).WithStatusCode(401);
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Warning && e.Message.Contains(entity.Id));
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Debug && e.Message.Contains("UpdatedAt", StringComparison.OrdinalIgnoreCase));
+    }
     #endregion
 
     #region PostCommitHookAsync

tests/CommunityToolkit.Datasync.Server.Test/Controllers/TableController_Create_Tests.cs

@@ -5,13 +5,49 @@
 using CommunityToolkit.Datasync.TestCommon;
 using CommunityToolkit.Datasync.TestCommon.Models;
 using Microsoft.AspNetCore.Mvc;
+using Microsoft.Extensions.Logging;
 using NSubstitute;
 
 namespace CommunityToolkit.Datasync.Server.Test.Controllers;
 
 [ExcludeFromCodeCoverage]
 public class TableController_Create_Tests : BaseTest
 {
+    [Fact]
+    public async Task CreateAsync_UnsafeEntityLogging_False_LogsIdOnly()
+    {
+        IAccessControlProvider<TableData> accessProvider = FakeAccessControlProvider<TableData>(TableOperation.Create, true);
+        IRepository<TableData> repository = FakeRepository<TableData>(null, false);
+        TableControllerOptions options = new() { UnsafeEntityLogging = false };
+        CapturingLogger logger = new();
+        ExposedTableController<TableData> controller = new(repository, accessProvider, options) { Logger = logger };
+        TableData entity = new() { Id = "0da7fb24-3606-442f-9f68-c47c6e7d09d4" };
+        controller.ControllerContext.HttpContext = CreateHttpContext(HttpMethod.Post, "https://localhost/table", entity);
+
+        _ = await controller.CreateAsync();
+
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Information && e.Message.Contains(entity.Id));
+        logger.Entries.Should().NotContain(e => e.Message.Contains("UpdatedAt", StringComparison.OrdinalIgnoreCase));
+        logger.Entries.Should().NotContain(e => e.LogLevel == LogLevel.Debug);
+    }
+
+    [Fact]
+    public async Task CreateAsync_UnsafeEntityLogging_True_LogsFullEntityAtDebug()
+    {
+        IAccessControlProvider<TableData> accessProvider = FakeAccessControlProvider<TableData>(TableOperation.Create, true);
+        IRepository<TableData> repository = FakeRepository<TableData>(null, false);
+        TableControllerOptions options = new() { UnsafeEntityLogging = true };
+        CapturingLogger logger = new();
+        ExposedTableController<TableData> controller = new(repository, accessProvider, options) { Logger = logger };
+        TableData entity = new() { Id = "0da7fb24-3606-442f-9f68-c47c6e7d09d4" };
+        controller.ControllerContext.HttpContext = CreateHttpContext(HttpMethod.Post, "https://localhost/table", entity);
+
+        _ = await controller.CreateAsync();
+
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Information && e.Message.Contains(entity.Id));
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Debug && e.Message.Contains("UpdatedAt", StringComparison.OrdinalIgnoreCase));
+    }
+
     [Fact]
     public async Task CreateAsync_Unauthorized_Throws()
     {

tests/CommunityToolkit.Datasync.Server.Test/Controllers/TableController_Read_Tests.cs

@@ -5,13 +5,51 @@
 using CommunityToolkit.Datasync.TestCommon;
 using CommunityToolkit.Datasync.TestCommon.Models;
 using Microsoft.AspNetCore.Mvc;
+using Microsoft.Extensions.Logging;
 using NSubstitute;
 
 namespace CommunityToolkit.Datasync.Server.Test.Controllers;
 
 [ExcludeFromCodeCoverage]
 public class TableController_Read_Tests : BaseTest
 {
+    [Fact]
+    public async Task ReadAsync_UnsafeEntityLogging_False_LogsIdOnly()
+    {
+        TableData entity = new() { Id = "0da7fb24-3606-442f-9f68-c47c6e7d09d4" };
+
+        IAccessControlProvider<TableData> accessProvider = FakeAccessControlProvider<TableData>(TableOperation.Read, true);
+        IRepository<TableData> repository = FakeRepository(entity, false);
+        TableControllerOptions options = new() { UnsafeEntityLogging = false };
+        CapturingLogger logger = new();
+        ExposedTableController<TableData> controller = new(repository, accessProvider, options) { Logger = logger };
+        controller.ControllerContext.HttpContext = CreateHttpContext(HttpMethod.Get, $"https://localhost/table/{entity.Id}");
+
+        _ = await controller.ReadAsync(entity.Id);
+
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Information && e.Message.Contains(entity.Id));
+        logger.Entries.Should().NotContain(e => e.Message.Contains("UpdatedAt", StringComparison.OrdinalIgnoreCase));
+        logger.Entries.Should().NotContain(e => e.LogLevel == LogLevel.Debug);
+    }
+
+    [Fact]
+    public async Task ReadAsync_UnsafeEntityLogging_True_LogsFullEntityAtDebug()
+    {
+        TableData entity = new() { Id = "0da7fb24-3606-442f-9f68-c47c6e7d09d4" };
+
+        IAccessControlProvider<TableData> accessProvider = FakeAccessControlProvider<TableData>(TableOperation.Read, true);
+        IRepository<TableData> repository = FakeRepository(entity, false);
+        TableControllerOptions options = new() { UnsafeEntityLogging = true };
+        CapturingLogger logger = new();
+        ExposedTableController<TableData> controller = new(repository, accessProvider, options) { Logger = logger };
+        controller.ControllerContext.HttpContext = CreateHttpContext(HttpMethod.Get, $"https://localhost/table/{entity.Id}");
+
+        _ = await controller.ReadAsync(entity.Id);
+
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Information && e.Message.Contains(entity.Id));
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Debug && e.Message.Contains("UpdatedAt", StringComparison.OrdinalIgnoreCase));
+    }
+
     [Fact]
     public async Task ReadAsync_RepositoryException_Throws()
     {

tests/CommunityToolkit.Datasync.Server.Test/Controllers/TableController_Replace_Tests.cs

@@ -5,13 +5,51 @@
 using CommunityToolkit.Datasync.TestCommon;
 using CommunityToolkit.Datasync.TestCommon.Models;
 using Microsoft.AspNetCore.Mvc;
+using Microsoft.Extensions.Logging;
 using NSubstitute;
 
 namespace CommunityToolkit.Datasync.Server.Test.Controllers;
 
 [ExcludeFromCodeCoverage]
 public class TableController_Replace_Tests : BaseTest
 {
+    [Fact]
+    public async Task ReplaceAsync_UnsafeEntityLogging_False_LogsIdOnly()
+    {
+        TableData entity = new() { Id = "0da7fb24-3606-442f-9f68-c47c6e7d09d4" };
+
+        IAccessControlProvider<TableData> accessProvider = FakeAccessControlProvider<TableData>(TableOperation.Update, true);
+        IRepository<TableData> repository = FakeRepository(entity, false);
+        TableControllerOptions options = new() { UnsafeEntityLogging = false };
+        CapturingLogger logger = new();
+        ExposedTableController<TableData> controller = new(repository, accessProvider, options) { Logger = logger };
+        controller.ControllerContext.HttpContext = CreateHttpContext(HttpMethod.Put, $"https://localhost/table/{entity.Id}", entity);
+
+        _ = await controller.ReplaceAsync(entity.Id);
+
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Information && e.Message.Contains(entity.Id));
+        logger.Entries.Should().NotContain(e => e.Message.Contains("UpdatedAt", StringComparison.OrdinalIgnoreCase));
+        logger.Entries.Should().NotContain(e => e.LogLevel == LogLevel.Debug);
+    }
+
+    [Fact]
+    public async Task ReplaceAsync_UnsafeEntityLogging_True_LogsFullEntityAtDebug()
+    {
+        TableData entity = new() { Id = "0da7fb24-3606-442f-9f68-c47c6e7d09d4" };
+
+        IAccessControlProvider<TableData> accessProvider = FakeAccessControlProvider<TableData>(TableOperation.Update, true);
+        IRepository<TableData> repository = FakeRepository(entity, false);
+        TableControllerOptions options = new() { UnsafeEntityLogging = true };
+        CapturingLogger logger = new();
+        ExposedTableController<TableData> controller = new(repository, accessProvider, options) { Logger = logger };
+        controller.ControllerContext.HttpContext = CreateHttpContext(HttpMethod.Put, $"https://localhost/table/{entity.Id}", entity);
+
+        _ = await controller.ReplaceAsync(entity.Id);
+
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Information && e.Message.Contains(entity.Id));
+        logger.Entries.Should().Contain(e => e.LogLevel == LogLevel.Debug && e.Message.Contains("UpdatedAt", StringComparison.OrdinalIgnoreCase));
+    }
+
     [Fact]
     public async Task ReplaceAsync_IdMismatch_Throws()
     {

tests/CommunityToolkit.Datasync.Server.Test/Helpers/CapturingLogger.cs

@@ -0,0 +1,50 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+// See the LICENSE file in the project root for more information.
+
+#nullable enable
+
+using Microsoft.Extensions.Logging;
+
+namespace CommunityToolkit.Datasync.Server.Test;
+
+/// <summary>
+/// A simple <see cref="ILogger"/> implementation that captures every log entry so that
+/// tests can assert on the level and rendered message of each log statement.
+/// </summary>
+[ExcludeFromCodeCoverage]
+internal sealed class CapturingLogger : ILogger
+{
+    /// <summary>
+    /// The list of captured log entries, in the order in which they were written.
+    /// </summary>
+    public List<LogEntry> Entries { get; } = [];
+
+    /// <inheritdoc />
+    public IDisposable BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance;
+
+    /// <inheritdoc />
+    public bool IsEnabled(LogLevel logLevel) => true;
+
+    /// <inheritdoc />
+    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
+    {
+        Entries.Add(new LogEntry(logLevel, formatter(state, exception)));
+    }
+
+    /// <summary>
+    /// A single captured log entry.
+    /// </summary>
+    /// <param name="LogLevel">The level the entry was logged at.</param>
+    /// <param name="Message">The rendered log message.</param>
+    public sealed record LogEntry(LogLevel LogLevel, string Message);
+
+    private sealed class NullScope : IDisposable
+    {
+        public static NullScope Instance { get; } = new();
+
+        public void Dispose()
+        {
+        }
+    }
+}

tests/CommunityToolkit.Datasync.Server.Test/Models/TableControllerOptions_Tests.cs

@@ -18,6 +18,7 @@ public void Ctor_DefaultsDontChange()
         sut.MaxTop.Should().Be(128000);
         sut.PageSize.Should().Be(100);
         sut.UnauthorizedStatusCode.Should().Be(StatusCodes.Status401Unauthorized);
+        sut.UnsafeEntityLogging.Should().BeFalse();
     }
 
     [Theory]
@@ -60,11 +61,12 @@ public void Ctor_ValidUnauthorizedStatusCode_Roundtrips(int statusCode)
     [Fact]
     public void Ctor_Roundtrips()
     {
-        TableControllerOptions sut = new() { EnableSoftDelete = true, MaxTop = 100, PageSize = 50, UnauthorizedStatusCode = 403 };
+        TableControllerOptions sut = new() { EnableSoftDelete = true, MaxTop = 100, PageSize = 50, UnauthorizedStatusCode = 403, UnsafeEntityLogging = true };
 
         sut.EnableSoftDelete.Should().BeTrue();
         sut.MaxTop.Should().Be(100);
         sut.PageSize.Should().Be(50);
         sut.UnauthorizedStatusCode.Should().Be(403);
+        sut.UnsafeEntityLogging.Should().BeTrue();
     }
 }