From 0eddd6c0032ab95d46eabe8e712788f1776eac6a Mon Sep 17 00:00:00 2001 From: Bart Koelman <10324372+bkoelman@users.noreply.github.com> Date: Sun, 25 May 2025 12:29:33 +0200 Subject: [PATCH 1/2] Log QueryLayer and Expression at Debug level --- package-versions.props | 1 + .../Middleware/TraceLogWriter.cs | 39 +++++++ .../ExpressionTreeFormatter.cs | 53 +++++++++ .../EntityFrameworkCoreRepository.cs | 4 + test/DiscoveryTests/DiscoveryTests.csproj | 3 +- test/DiscoveryTests/LoggingTests.cs | 52 +++++++++ .../Mixed/AtomicTraceLoggingTests.cs | 2 +- .../IntegrationTests/Logging/Fruit.cs | 3 + .../IntegrationTests/Logging/LoggingFakers.cs | 2 + .../IntegrationTests/Logging/LoggingTests.cs | 102 +++++++++++++++++- .../JsonApiDotNetCoreTests.csproj | 1 + 11 files changed, 256 insertions(+), 6 deletions(-) create mode 100644 src/JsonApiDotNetCore/Queries/QueryableBuilding/ExpressionTreeFormatter.cs create mode 100644 test/DiscoveryTests/LoggingTests.cs diff --git a/package-versions.props b/package-versions.props index d14ed838be..0403a83c07 100644 --- a/package-versions.props +++ b/package-versions.props @@ -22,6 +22,7 @@ 9.0.* 14.4.* 13.0.* + 4.1.* 2.3.* 8.*-* 9.0.* diff --git a/src/JsonApiDotNetCore/Middleware/TraceLogWriter.cs b/src/JsonApiDotNetCore/Middleware/TraceLogWriter.cs index 70ed7fdd01..23e6733a44 100644 --- a/src/JsonApiDotNetCore/Middleware/TraceLogWriter.cs +++ b/src/JsonApiDotNetCore/Middleware/TraceLogWriter.cs @@ -1,3 +1,4 @@ +using System.Linq.Expressions; using System.Reflection; using System.Runtime.CompilerServices; using System.Text; @@ -5,6 +6,8 @@ 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(); } diff --git a/src/JsonApiDotNetCore/Queries/QueryableBuilding/ExpressionTreeFormatter.cs b/src/JsonApiDotNetCore/Queries/QueryableBuilding/ExpressionTreeFormatter.cs new file mode 100644 index 0000000000..c6b1bc4bb3 --- /dev/null +++ b/src/JsonApiDotNetCore/Queries/QueryableBuilding/ExpressionTreeFormatter.cs @@ -0,0 +1,53 @@ +using System.Linq.Expressions; +using System.Reflection; + +namespace JsonApiDotNetCore.Queries.QueryableBuilding; + +/// +/// Converts a to readable text, if the AgileObjects.ReadableExpressions NuGet package is referenced. +/// +internal sealed class ExpressionTreeFormatter +{ + private static readonly Lazy 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; + } + } +} diff --git a/src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs b/src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs index 214987828a..f4c9af37c0 100644 --- a/src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs +++ b/src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs @@ -122,6 +122,8 @@ protected virtual IQueryable ApplyQueryLayer(QueryLayer queryLayer) ArgumentNullException.ThrowIfNull(queryLayer); + _traceWriter.LogDebug(queryLayer); + using (CodeTimingSessionManager.Current.Measure("Convert QueryLayer to System.Expression")) { IQueryable source = GetAll(); @@ -151,6 +153,8 @@ protected virtual IQueryable 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(expression); diff --git a/test/DiscoveryTests/DiscoveryTests.csproj b/test/DiscoveryTests/DiscoveryTests.csproj index 825056684e..11567b9113 100644 --- a/test/DiscoveryTests/DiscoveryTests.csproj +++ b/test/DiscoveryTests/DiscoveryTests.csproj @@ -1,4 +1,4 @@ - + net9.0;net8.0 @@ -15,5 +15,6 @@ + diff --git a/test/DiscoveryTests/LoggingTests.cs b/test/DiscoveryTests/LoggingTests.cs new file mode 100644 index 0000000000..9afb7c7888 --- /dev/null +++ b/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(options => options.UseInMemoryDatabase(Guid.NewGuid().ToString())); + builder.Services.AddJsonApi(); + builder.WebHost.UseTestServer(); + await using WebApplication app = builder.Build(); + + var resourceGraph = app.Services.GetRequiredService(); + ResourceType resourceType = resourceGraph.GetResourceType(); + + var repository = app.Services.GetRequiredService>(); + + // Act + _ = await repository.GetAsync(new QueryLayer(resourceType), CancellationToken.None); + + // Assert + IReadOnlyList 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 PrivateResources => Set(); + } +} diff --git a/test/JsonApiDotNetCoreTests/IntegrationTests/AtomicOperations/Mixed/AtomicTraceLoggingTests.cs b/test/JsonApiDotNetCoreTests/IntegrationTests/AtomicOperations/Mixed/AtomicTraceLoggingTests.cs index 6eb2ce3a37..0ea01e7d33 100644 --- a/test/JsonApiDotNetCoreTests/IntegrationTests/AtomicOperations/Mixed/AtomicTraceLoggingTests.cs +++ b/test/JsonApiDotNetCoreTests/IntegrationTests/AtomicOperations/Mixed/AtomicTraceLoggingTests.cs @@ -22,7 +22,7 @@ public AtomicTraceLoggingTests(IntegrationTestContext { 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); diff --git a/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/Fruit.cs b/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/Fruit.cs index fd0fbf0dfa..4e26c558ff 100644 --- a/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/Fruit.cs +++ b/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/Fruit.cs @@ -10,4 +10,7 @@ public abstract class Fruit : Identifiable { [Attr] public abstract string Color { get; } + + [Attr] + public double WeightInKilograms { get; set; } } diff --git a/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingFakers.cs b/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingFakers.cs index a66cdcdf55..aa34ff32f5 100644 --- a/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingFakers.cs +++ b/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingFakers.cs @@ -15,10 +15,12 @@ internal sealed class LoggingFakers private readonly Lazy> _lazyBananaFaker = new(() => new Faker() .MakeDeterministic() + .RuleFor(banana => banana.WeightInKilograms, faker => faker.Random.Double(.2, .3)) .RuleFor(banana => banana.LengthInCentimeters, faker => faker.Random.Double(10, 25))); private readonly Lazy> _lazyPeachFaker = new(() => new Faker() .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 => _lazyAuditEntryFaker.Value; diff --git a/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingTests.cs b/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingTests.cs index 9fbd9e8051..4d35403f9e 100644 --- a/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingTests.cs +++ b/test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingTests.cs @@ -152,9 +152,9 @@ await _testContext.RunOnDatabaseAsync(async dbContext => responseDocument.Should().BeEmpty(); - IReadOnlyList 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 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,6 +332,7 @@ [TRACE] Entering AddToToManyRelationshipAsync(leftResource: null, leftId: {{exis { "Color": "Red/Yellow", "DiameterInCentimeters": 0, + "WeightInKilograms": 0, "Id": {{existingPeach.Id}}, "StringId": "{{existingPeach.StringId}}" } @@ -336,4 +340,94 @@ [TRACE] Entering AddToToManyRelationshipAsync(leftResource: null, leftId: {{exis """ }, 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(); + 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(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 + { + Include: fruits + Filter: equals(id,'{{bowl.StringId}}') + Selection + { + FieldSelectors + { + id + fruits: QueryLayer + { + Filter: greaterThan(weightInKilograms,'0.1') + Sort: -id + Pagination: Page number: 1, size: 10 + Selection + { + FieldSelectors + { + 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() + }) + """); + } } diff --git a/test/JsonApiDotNetCoreTests/JsonApiDotNetCoreTests.csproj b/test/JsonApiDotNetCoreTests/JsonApiDotNetCoreTests.csproj index 6bc5a666a1..bdfea682d9 100644 --- a/test/JsonApiDotNetCoreTests/JsonApiDotNetCoreTests.csproj +++ b/test/JsonApiDotNetCoreTests/JsonApiDotNetCoreTests.csproj @@ -12,6 +12,7 @@ + From 0ccfcc2bd66a29d896dfd2ae39505af30c1f21ca Mon Sep 17 00:00:00 2001 From: Bart Koelman <10324372+bkoelman@users.noreply.github.com> Date: Sun, 25 May 2025 12:51:11 +0200 Subject: [PATCH 2/2] Replace debugger visualizer link in docs --- docs/usage/faq.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/usage/faq.md b/docs/usage/faq.md index dacd35889b..567f17525a 100644 --- a/docs/usage/faq.md +++ b/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.