Log QueryLayer and LINQ expression at Debug level

docs/usage/faq.md

@@ -160,7 +160,7 @@ If there's no LINQ provider available, the example [here](https://github.com/jso
 which produces SQL and uses [Dapper](https://github.com/DapperLib/Dapper) for data access.
 
 > [!TIP]
-> [ExpressionTreeVisualizer](https://github.com/zspitz/ExpressionTreeVisualizer) is very helpful in trying to debug LINQ expression trees!
+> [ReadableExpressions](https://github.com/agileobjects/ReadableExpressions) is very helpful in trying to debug LINQ expression trees!
 
 #### I love JsonApiDotNetCore! How can I support the team?
 The best way to express your gratitude is by starring our repository.

package-versions.props

@@ -22,6 +22,7 @@
     <MicrosoftApiServerVersion>9.0.*</MicrosoftApiServerVersion>
     <NSwagApiClientVersion>14.4.*</NSwagApiClientVersion>
     <NewtonsoftJsonVersion>13.0.*</NewtonsoftJsonVersion>
+    <ReadableExpressionsVersion>4.1.*</ReadableExpressionsVersion>
     <ScalarAspNetCoreVersion>2.3.*</ScalarAspNetCoreVersion>
     <SwashbuckleVersion>8.*-*</SwashbuckleVersion>
     <SystemTextJsonVersion>9.0.*</SystemTextJsonVersion>

src/JsonApiDotNetCore/Middleware/TraceLogWriter.cs

@@ -1,10 +1,13 @@
+using System.Linq.Expressions;
 using System.Reflection;
 using System.Runtime.CompilerServices;
 using System.Text;
 using System.Text.Encodings.Web;
 using System.Text.Json;
 using System.Text.Json.Serialization;
 using JsonApiDotNetCore.Configuration;
+using JsonApiDotNetCore.Queries;
+using JsonApiDotNetCore.Queries.QueryableBuilding;
 using JsonApiDotNetCore.Resources;
 using JsonApiDotNetCore.Resources.Annotations;
 using Microsoft.Extensions.Logging;
@@ -204,9 +207,45 @@ private static string SerializeObject(object? value)
         }
     }
 
+    public void LogDebug(QueryLayer queryLayer)
+    {
+        ArgumentNullException.ThrowIfNull(queryLayer);
+
+        LogQueryLayer(queryLayer);
+    }
+
+    public void LogDebug(Expression expression)
+    {
+        ArgumentNullException.ThrowIfNull(expression);
+
+        if (_logger.IsEnabled(LogLevel.Debug))
+        {
+            string? text = ExpressionTreeFormatter.Instance.GetText(expression);
+
+            if (text != null)
+            {
+                LogExpression(text);
+            }
+            else
+            {
+                LogReadableExpressionsAssemblyUnavailable();
+            }
+        }
+    }
+
     [LoggerMessage(Level = LogLevel.Trace, SkipEnabledCheck = true, Message = "Entering {MemberName}({ParameterValues})")]
     private partial void LogEnteringMemberWithParameters(string memberName, string parameterValues);
 
     [LoggerMessage(Level = LogLevel.Trace, SkipEnabledCheck = true, Message = "Entering {MemberName}()")]
     private partial void LogEnteringMember(string memberName);
+
+    [LoggerMessage(Level = LogLevel.Debug, Message = "QueryLayer: {queryLayer}")]
+    private partial void LogQueryLayer(QueryLayer queryLayer);
+
+    [LoggerMessage(Level = LogLevel.Debug, SkipEnabledCheck = true, Message = "Expression tree: {expression}")]
+    private partial void LogExpression(string expression);
+
+    [LoggerMessage(Level = LogLevel.Debug, SkipEnabledCheck = true,
+        Message = "Failed to load assembly. To log expression trees, add a NuGet reference to 'AgileObjects.ReadableExpressions' in your project.")]
+    private partial void LogReadableExpressionsAssemblyUnavailable();
 }

src/JsonApiDotNetCore/Queries/QueryableBuilding/ExpressionTreeFormatter.cs

@@ -0,0 +1,53 @@
+using System.Linq.Expressions;
+using System.Reflection;
+
+namespace JsonApiDotNetCore.Queries.QueryableBuilding;
+
+/// <summary>
+/// Converts a <see cref="Expression" /> to readable text, if the AgileObjects.ReadableExpressions NuGet package is referenced.
+/// </summary>
+internal sealed class ExpressionTreeFormatter
+{
+    private static readonly Lazy<MethodInvoker?> LazyToReadableStringMethod = new(GetToReadableStringMethod, LazyThreadSafetyMode.ExecutionAndPublication);
+
+    public static ExpressionTreeFormatter Instance { get; } = new();
+
+    private ExpressionTreeFormatter()
+    {
+    }
+
+    private static MethodInvoker? GetToReadableStringMethod()
+    {
+        Assembly? assembly = TryLoadAssembly();
+        Type? type = assembly?.GetType("AgileObjects.ReadableExpressions.ExpressionExtensions", false);
+        MethodInfo? method = type?.GetMethods(BindingFlags.Public | BindingFlags.Static).FirstOrDefault(method => method.Name == "ToReadableString");
+        return method != null ? MethodInvoker.Create(method) : null;
+    }
+
+    private static Assembly? TryLoadAssembly()
+    {
+        try
+        {
+            return Assembly.Load("AgileObjects.ReadableExpressions");
+        }
+        catch (Exception exception) when (exception is ArgumentException or IOException or BadImageFormatException)
+        {
+        }
+
+        return null;
+    }
+
+    public string? GetText(Expression expression)
+    {
+        ArgumentNullException.ThrowIfNull(expression);
+
+        try
+        {
+            return LazyToReadableStringMethod.Value?.Invoke(null, expression, null) as string;
+        }
+        catch (Exception exception) when (exception is TargetException or InvalidOperationException or TargetParameterCountException or NotSupportedException)
+        {
+            return null;
+        }
+    }
+}

src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs

@@ -122,6 +122,8 @@ protected virtual IQueryable<TResource> ApplyQueryLayer(QueryLayer queryLayer)
 
         ArgumentNullException.ThrowIfNull(queryLayer);
 
+        _traceWriter.LogDebug(queryLayer);
+
         using (CodeTimingSessionManager.Current.Measure("Convert QueryLayer to System.Expression"))
         {
             IQueryable<TResource> source = GetAll();
@@ -151,6 +153,8 @@ protected virtual IQueryable<TResource> ApplyQueryLayer(QueryLayer queryLayer)
             var context = QueryableBuilderContext.CreateRoot(source, typeof(Queryable), _dbContext.Model, null);
             Expression expression = builder.ApplyQuery(queryLayer, context);
 
+            _traceWriter.LogDebug(expression);
+
             using (CodeTimingSessionManager.Current.Measure("Convert System.Expression to IQueryable"))
             {
                 return source.Provider.CreateQuery<TResource>(expression);

test/DiscoveryTests/DiscoveryTests.csproj

@@ -1,4 +1,4 @@
-<Project Sdk="Microsoft.NET.Sdk">
+<Project Sdk="Microsoft.NET.Sdk">
   <PropertyGroup>
     <TargetFrameworks>net9.0;net8.0</TargetFrameworks>
   </PropertyGroup>
@@ -15,5 +15,6 @@
     <PackageReference Include="GitHubActionsTestLogger" Version="$(GitHubActionsTestLoggerVersion)" PrivateAssets="All" />
     <PackageReference Include="Microsoft.NET.Test.Sdk" Version="$(TestSdkVersion)" />
     <PackageReference Include="Microsoft.AspNetCore.OpenApi" Condition="'$(TargetFramework)' != 'net8.0'" Version="$(AspNetCoreVersion)" />
+    <PackageReference Include="Microsoft.EntityFrameworkCore.InMemory" Version="$(EntityFrameworkCoreVersion)" />
   </ItemGroup>
 </Project>

test/DiscoveryTests/LoggingTests.cs

@@ -0,0 +1,52 @@
+using FluentAssertions;
+using JsonApiDotNetCore.Configuration;
+using JsonApiDotNetCore.Queries;
+using JsonApiDotNetCore.Repositories;
+using Microsoft.AspNetCore.Builder;
+using Microsoft.AspNetCore.TestHost;
+using Microsoft.EntityFrameworkCore;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
+using TestBuildingBlocks;
+using Xunit;
+
+namespace DiscoveryTests;
+
+public sealed class LoggingTests
+{
+    [Fact]
+    public async Task Logs_message_to_add_NuGet_reference()
+    {
+        // Arrange
+        using var loggerProvider =
+            new CapturingLoggerProvider((category, _) => category.StartsWith("JsonApiDotNetCore.Repositories", StringComparison.Ordinal));
+
+        WebApplicationBuilder builder = WebApplication.CreateEmptyBuilder(new WebApplicationOptions());
+        builder.Logging.AddProvider(loggerProvider);
+        builder.Logging.SetMinimumLevel(LogLevel.Debug);
+        builder.Services.AddDbContext<TestDbContext>(options => options.UseInMemoryDatabase(Guid.NewGuid().ToString()));
+        builder.Services.AddJsonApi<TestDbContext>();
+        builder.WebHost.UseTestServer();
+        await using WebApplication app = builder.Build();
+
+        var resourceGraph = app.Services.GetRequiredService<IResourceGraph>();
+        ResourceType resourceType = resourceGraph.GetResourceType<PrivateResource>();
+
+        var repository = app.Services.GetRequiredService<IResourceRepository<PrivateResource, int>>();
+
+        // Act
+        _ = await repository.GetAsync(new QueryLayer(resourceType), CancellationToken.None);
+
+        // Assert
+        IReadOnlyList<string> logLines = loggerProvider.GetLines();
+
+        logLines.Should().Contain(
+            "[DEBUG] Failed to load assembly. To log expression trees, add a NuGet reference to 'AgileObjects.ReadableExpressions' in your project.");
+    }
+
+    private sealed class TestDbContext(DbContextOptions options)
+        : DbContext(options)
+    {
+        public DbSet<PrivateResource> PrivateResources => Set<PrivateResource>();
+    }
+}

test/JsonApiDotNetCoreTests/IntegrationTests/AtomicOperations/Mixed/AtomicTraceLoggingTests.cs

@@ -22,7 +22,7 @@ public AtomicTraceLoggingTests(IntegrationTestContext<TestableStartup<Operations
         testContext.ConfigureLogging(options =>
         {
             var loggerProvider = new CapturingLoggerProvider((category, level) =>
-                level >= LogLevel.Trace && category.StartsWith("JsonApiDotNetCore.", StringComparison.Ordinal));
+                level == LogLevel.Trace && category.StartsWith("JsonApiDotNetCore.", StringComparison.Ordinal));
 
             options.AddProvider(loggerProvider);
             options.SetMinimumLevel(LogLevel.Trace);

test/JsonApiDotNetCoreTests/IntegrationTests/Logging/Fruit.cs

@@ -10,4 +10,7 @@ public abstract class Fruit : Identifiable<long>
 {
     [Attr]
     public abstract string Color { get; }
+
+    [Attr]
+    public double WeightInKilograms { get; set; }
 }

test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingFakers.cs

@@ -15,10 +15,12 @@ internal sealed class LoggingFakers
 
     private readonly Lazy<Faker<Banana>> _lazyBananaFaker = new(() => new Faker<Banana>()
         .MakeDeterministic()
+        .RuleFor(banana => banana.WeightInKilograms, faker => faker.Random.Double(.2, .3))
         .RuleFor(banana => banana.LengthInCentimeters, faker => faker.Random.Double(10, 25)));
 
     private readonly Lazy<Faker<Peach>> _lazyPeachFaker = new(() => new Faker<Peach>()
         .MakeDeterministic()
+        .RuleFor(peach => peach.WeightInKilograms, faker => faker.Random.Double(.2, .3))
         .RuleFor(peach => peach.DiameterInCentimeters, faker => faker.Random.Double(6, 7.5)));
 
     public Faker<AuditEntry> AuditEntry => _lazyAuditEntryFaker.Value;

test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingTests.cs

@@ -152,9 +152,9 @@ await _testContext.RunOnDatabaseAsync(async dbContext =>
 
         responseDocument.Should().BeEmpty();
 
-        IReadOnlyList<string> logLines = loggerProvider.GetLines();
+        string[] traceLines = loggerProvider.GetMessages().Where(message => message.LogLevel == LogLevel.Trace).Select(message => message.ToString()).ToArray();
 
-        logLines.Should().BeEquivalentTo(new[]
+        traceLines.Should().BeEquivalentTo(new[]
         {
             $$"""
             [TRACE] Received POST request at 'http://localhost/fruitBowls/{{existingBowl.StringId}}/relationships/fruits' with body: <<{
@@ -215,6 +215,7 @@ [TRACE] Entering AddToToManyRelationshipAsync(leftResource: null, leftId: {{exis
               {
                 "Color": "Yellow",
                 "LengthInCentimeters": {{existingBanana.LengthInCentimeters.ToString(CultureInfo.InvariantCulture)}},
+                "WeightInKilograms": {{existingBanana.WeightInKilograms.ToString(CultureInfo.InvariantCulture)}},
                 "Id": {{existingBanana.Id}},
                 "StringId": "{{existingBanana.StringId}}"
               }
@@ -262,9 +263,9 @@ await _testContext.RunOnDatabaseAsync(async dbContext =>
 
         responseDocument.Should().BeEmpty();
 
-        IReadOnlyList<string> logLines = loggerProvider.GetLines();
+        string[] traceLines = loggerProvider.GetMessages().Where(message => message.LogLevel == LogLevel.Trace).Select(message => message.ToString()).ToArray();
 
-        logLines.Should().BeEquivalentTo(new[]
+        traceLines.Should().BeEquivalentTo(new[]
         {
             $$"""
             [TRACE] Received POST request at 'http://localhost/fruitBowls/{{existingBowl.StringId}}/relationships/fruits' with body: <<{
@@ -281,6 +282,7 @@ [TRACE] Entering PostRelationshipAsync(id: {{existingBowl.StringId}}, relationsh
               {
                 "Color": "Red/Yellow",
                 "DiameterInCentimeters": 0,
+                "WeightInKilograms": 0,
                 "Id": {{existingPeach.Id}},
                 "StringId": "{{existingPeach.StringId}}"
               }
@@ -291,6 +293,7 @@ [TRACE] Entering AddToToManyRelationshipAsync(leftId: {{existingBowl.StringId}},
               {
                 "Color": "Red/Yellow",
                 "DiameterInCentimeters": 0,
+                "WeightInKilograms": 0,
                 "Id": {{existingPeach.Id}},
                 "StringId": "{{existingPeach.StringId}}"
               }
@@ -329,11 +332,102 @@ [TRACE] Entering AddToToManyRelationshipAsync(leftResource: null, leftId: {{exis
               {
                 "Color": "Red/Yellow",
                 "DiameterInCentimeters": 0,
+                "WeightInKilograms": 0,
                 "Id": {{existingPeach.Id}},
                 "StringId": "{{existingPeach.StringId}}"
               }
             ])
             """
         }, options => options.Using(IgnoreLineEndingsComparer.Instance).WithStrictOrdering());
     }
+
+    [Fact]
+    public async Task Logs_query_layer_and_expression_at_Debug_level()
+    {
+        // Arrange
+        var loggerProvider = _testContext.Factory.Services.GetRequiredService<CapturingLoggerProvider>();
+        loggerProvider.Clear();
+
+        var bowl = new FruitBowl();
+        bowl.Fruits.Add(_fakers.Peach.GenerateOne());
+
+        await _testContext.RunOnDatabaseAsync(async dbContext =>
+        {
+            dbContext.FruitBowls.Add(bowl);
+            await dbContext.SaveChangesAsync();
+        });
+
+        string route = $"/fruitBowls/{bowl.StringId}/fruits?filter=greaterThan(weightInKilograms,'0.1')&fields[peaches]=color&sort=-id";
+
+        // Act
+        (HttpResponseMessage httpResponse, string responseDocument) = await _testContext.ExecuteGetAsync<string>(route);
+
+        // Assert
+        httpResponse.ShouldHaveStatusCode(HttpStatusCode.OK);
+
+        responseDocument.Should().NotBeEmpty();
+
+        LogMessage queryLayerMessage = loggerProvider.GetMessages().Should()
+            .ContainSingle(message => message.LogLevel == LogLevel.Debug && message.Text.StartsWith("QueryLayer:", StringComparison.Ordinal)).Subject;
+
+        queryLayerMessage.Text.Should().Be($$"""
+            QueryLayer: QueryLayer<FruitBowl>
+            {
+              Include: fruits
+              Filter: equals(id,'{{bowl.StringId}}')
+              Selection
+              {
+                FieldSelectors<FruitBowl>
+                {
+                  id
+                  fruits: QueryLayer<Fruit>
+                  {
+                    Filter: greaterThan(weightInKilograms,'0.1')
+                    Sort: -id
+                    Pagination: Page number: 1, size: 10
+                    Selection
+                    {
+                      FieldSelectors<Peach>
+                      {
+                        color
+                        id
+                      }
+                    }
+                  }
+                }
+              }
+            }
+
+            """);
+
+        LogMessage expressionMessage = loggerProvider.GetMessages().Should().ContainSingle(message =>
+            message.LogLevel == LogLevel.Debug && message.Text.StartsWith("Expression tree:", StringComparison.Ordinal)).Subject;
+
+        expressionMessage.Text.Should().Be("""
+            Expression tree: [Microsoft.EntityFrameworkCore.Query.EntityQueryRootExpression]
+                .AsNoTrackingWithIdentityResolution()
+                .Include("Fruits")
+                .Where(fruitBowl => fruitBowl.Id == value)
+                .Select(
+                    fruitBowl => new FruitBowl
+                    {
+                        Id = fruitBowl.Id,
+                        Fruits = fruitBowl.Fruits
+                            .Where(fruit => fruit.WeightInKilograms > value)
+                            .OrderByDescending(fruit => fruit.Id)
+                            .Take(value)
+                            .Select(
+                                fruit => (fruit.GetType() == value)
+                                    ? (Fruit)new Peach
+                                    {
+                                        Id = fruit.Id,
+                                        WeightInKilograms = fruit.WeightInKilograms,
+                                        DiameterInCentimeters = ((Peach)fruit).DiameterInCentimeters,
+                                        Id = fruit.Id
+                                    }
+                                    : fruit)
+                            .ToHashSet()
+                    })
+            """);
+    }
 }