Log QueryLayer and LINQ expression at Debug level (#1732)

* Log QueryLayer and Expression at Debug level
* Replace debugger visualizer link in docs

Author: bkoelman

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;