Skip to content

Commit 99c9a95

Browse files
bkoelmanbkoelman
authored
Log QueryLayer and LINQ expression at Debug level (#1732)
* Log QueryLayer and Expression at Debug level * Replace debugger visualizer link in docs
1 parent b6b56b0 commit 99c9a95

File tree

12 files changed

+257
-7
lines changed

12 files changed

+257
-7
lines changed

‎docs/usage/faq.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -160,7 +160,7 @@ If there's no LINQ provider available, the example [here](https://github.com/jso
160160
which produces SQL and uses [Dapper](https://github.com/DapperLib/Dapper) for data access.
161161

162162
> [!TIP]
163-
> [ExpressionTreeVisualizer](https://github.com/zspitz/ExpressionTreeVisualizer) is very helpful in trying to debug LINQ expression trees!
163+
> [ReadableExpressions](https://github.com/agileobjects/ReadableExpressions) is very helpful in trying to debug LINQ expression trees!
164164
165165
#### I love JsonApiDotNetCore! How can I support the team?
166166
The best way to express your gratitude is by starring our repository.

‎package-versions.props

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222
<MicrosoftApiServerVersion>9.0.*</MicrosoftApiServerVersion>
2323
<NSwagApiClientVersion>14.4.*</NSwagApiClientVersion>
2424
<NewtonsoftJsonVersion>13.0.*</NewtonsoftJsonVersion>
25+
<ReadableExpressionsVersion>4.1.*</ReadableExpressionsVersion>
2526
<ScalarAspNetCoreVersion>2.3.*</ScalarAspNetCoreVersion>
2627
<SwashbuckleVersion>8.*-*</SwashbuckleVersion>
2728
<SystemTextJsonVersion>9.0.*</SystemTextJsonVersion>

‎src/JsonApiDotNetCore/Middleware/TraceLogWriter.cs

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,13 @@
1+
using System.Linq.Expressions;
12
using System.Reflection;
23
using System.Runtime.CompilerServices;
34
using System.Text;
45
using System.Text.Encodings.Web;
56
using System.Text.Json;
67
using System.Text.Json.Serialization;
78
using JsonApiDotNetCore.Configuration;
9+
using JsonApiDotNetCore.Queries;
10+
using JsonApiDotNetCore.Queries.QueryableBuilding;
811
using JsonApiDotNetCore.Resources;
912
using JsonApiDotNetCore.Resources.Annotations;
1013
using Microsoft.Extensions.Logging;
@@ -204,9 +207,45 @@ private static string SerializeObject(object? value)
204207
}
205208
}
206209

210+
public void LogDebug(QueryLayer queryLayer)
211+
{
212+
ArgumentNullException.ThrowIfNull(queryLayer);
213+
214+
LogQueryLayer(queryLayer);
215+
}
216+
217+
public void LogDebug(Expression expression)
218+
{
219+
ArgumentNullException.ThrowIfNull(expression);
220+
221+
if (_logger.IsEnabled(LogLevel.Debug))
222+
{
223+
string? text = ExpressionTreeFormatter.Instance.GetText(expression);
224+
225+
if (text != null)
226+
{
227+
LogExpression(text);
228+
}
229+
else
230+
{
231+
LogReadableExpressionsAssemblyUnavailable();
232+
}
233+
}
234+
}
235+
207236
[LoggerMessage(Level = LogLevel.Trace, SkipEnabledCheck = true, Message = "Entering {MemberName}({ParameterValues})")]
208237
private partial void LogEnteringMemberWithParameters(string memberName, string parameterValues);
209238

210239
[LoggerMessage(Level = LogLevel.Trace, SkipEnabledCheck = true, Message = "Entering {MemberName}()")]
211240
private partial void LogEnteringMember(string memberName);
241+
242+
[LoggerMessage(Level = LogLevel.Debug, Message = "QueryLayer: {queryLayer}")]
243+
private partial void LogQueryLayer(QueryLayer queryLayer);
244+
245+
[LoggerMessage(Level = LogLevel.Debug, SkipEnabledCheck = true, Message = "Expression tree: {expression}")]
246+
private partial void LogExpression(string expression);
247+
248+
[LoggerMessage(Level = LogLevel.Debug, SkipEnabledCheck = true,
249+
Message = "Failed to load assembly. To log expression trees, add a NuGet reference to 'AgileObjects.ReadableExpressions' in your project.")]
250+
private partial void LogReadableExpressionsAssemblyUnavailable();
212251
}

‎src/JsonApiDotNetCore/Queries/QueryableBuilding/ExpressionTreeFormatter.cs

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,53 @@
1+
using System.Linq.Expressions;
2+
using System.Reflection;
3+
4+
namespace JsonApiDotNetCore.Queries.QueryableBuilding;
5+
6+
/// <summary>
7+
/// Converts a <see cref="Expression" /> to readable text, if the AgileObjects.ReadableExpressions NuGet package is referenced.
8+
/// </summary>
9+
internal sealed class ExpressionTreeFormatter
10+
{
11+
private static readonly Lazy<MethodInvoker?> LazyToReadableStringMethod = new(GetToReadableStringMethod, LazyThreadSafetyMode.ExecutionAndPublication);
12+
13+
public static ExpressionTreeFormatter Instance { get; } = new();
14+
15+
private ExpressionTreeFormatter()
16+
{
17+
}
18+
19+
private static MethodInvoker? GetToReadableStringMethod()
20+
{
21+
Assembly? assembly = TryLoadAssembly();
22+
Type? type = assembly?.GetType("AgileObjects.ReadableExpressions.ExpressionExtensions", false);
23+
MethodInfo? method = type?.GetMethods(BindingFlags.Public | BindingFlags.Static).FirstOrDefault(method => method.Name == "ToReadableString");
24+
return method != null ? MethodInvoker.Create(method) : null;
25+
}
26+
27+
private static Assembly? TryLoadAssembly()
28+
{
29+
try
30+
{
31+
return Assembly.Load("AgileObjects.ReadableExpressions");
32+
}
33+
catch (Exception exception) when (exception is ArgumentException or IOException or BadImageFormatException)
34+
{
35+
}
36+
37+
return null;
38+
}
39+
40+
public string? GetText(Expression expression)
41+
{
42+
ArgumentNullException.ThrowIfNull(expression);
43+
44+
try
45+
{
46+
return LazyToReadableStringMethod.Value?.Invoke(null, expression, null) as string;
47+
}
48+
catch (Exception exception) when (exception is TargetException or InvalidOperationException or TargetParameterCountException or NotSupportedException)
49+
{
50+
return null;
51+
}
52+
}
53+
}

‎src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -122,6 +122,8 @@ protected virtual IQueryable<TResource> ApplyQueryLayer(QueryLayer queryLayer)
122122

123123
ArgumentNullException.ThrowIfNull(queryLayer);
124124

125+
_traceWriter.LogDebug(queryLayer);
126+
125127
using (CodeTimingSessionManager.Current.Measure("Convert QueryLayer to System.Expression"))
126128
{
127129
IQueryable<TResource> source = GetAll();
@@ -151,6 +153,8 @@ protected virtual IQueryable<TResource> ApplyQueryLayer(QueryLayer queryLayer)
151153
var context = QueryableBuilderContext.CreateRoot(source, typeof(Queryable), _dbContext.Model, null);
152154
Expression expression = builder.ApplyQuery(queryLayer, context);
153155

156+
_traceWriter.LogDebug(expression);
157+
154158
using (CodeTimingSessionManager.Current.Measure("Convert System.Expression to IQueryable"))
155159
{
156160
return source.Provider.CreateQuery<TResource>(expression);

‎test/DiscoveryTests/DiscoveryTests.csproj

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
<Project Sdk="Microsoft.NET.Sdk">
1+
<Project Sdk="Microsoft.NET.Sdk">
22
<PropertyGroup>
33
<TargetFrameworks>net9.0;net8.0</TargetFrameworks>
44
</PropertyGroup>
@@ -15,5 +15,6 @@
1515
<PackageReference Include="GitHubActionsTestLogger" Version="$(GitHubActionsTestLoggerVersion)" PrivateAssets="All" />
1616
<PackageReference Include="Microsoft.NET.Test.Sdk" Version="$(TestSdkVersion)" />
1717
<PackageReference Include="Microsoft.AspNetCore.OpenApi" Condition="'$(TargetFramework)' != 'net8.0'" Version="$(AspNetCoreVersion)" />
18+
<PackageReference Include="Microsoft.EntityFrameworkCore.InMemory" Version="$(EntityFrameworkCoreVersion)" />
1819
</ItemGroup>
1920
</Project>

‎test/DiscoveryTests/LoggingTests.cs

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
using FluentAssertions;
2+
using JsonApiDotNetCore.Configuration;
3+
using JsonApiDotNetCore.Queries;
4+
using JsonApiDotNetCore.Repositories;
5+
using Microsoft.AspNetCore.Builder;
6+
using Microsoft.AspNetCore.TestHost;
7+
using Microsoft.EntityFrameworkCore;
8+
using Microsoft.Extensions.DependencyInjection;
9+
using Microsoft.Extensions.Logging;
10+
using TestBuildingBlocks;
11+
using Xunit;
12+
13+
namespace DiscoveryTests;
14+
15+
public sealed class LoggingTests
16+
{
17+
[Fact]
18+
public async Task Logs_message_to_add_NuGet_reference()
19+
{
20+
// Arrange
21+
using var loggerProvider =
22+
new CapturingLoggerProvider((category, _) => category.StartsWith("JsonApiDotNetCore.Repositories", StringComparison.Ordinal));
23+
24+
WebApplicationBuilder builder = WebApplication.CreateEmptyBuilder(new WebApplicationOptions());
25+
builder.Logging.AddProvider(loggerProvider);
26+
builder.Logging.SetMinimumLevel(LogLevel.Debug);
27+
builder.Services.AddDbContext<TestDbContext>(options => options.UseInMemoryDatabase(Guid.NewGuid().ToString()));
28+
builder.Services.AddJsonApi<TestDbContext>();
29+
builder.WebHost.UseTestServer();
30+
await using WebApplication app = builder.Build();
31+
32+
var resourceGraph = app.Services.GetRequiredService<IResourceGraph>();
33+
ResourceType resourceType = resourceGraph.GetResourceType<PrivateResource>();
34+
35+
var repository = app.Services.GetRequiredService<IResourceRepository<PrivateResource, int>>();
36+
37+
// Act
38+
_ = await repository.GetAsync(new QueryLayer(resourceType), CancellationToken.None);
39+
40+
// Assert
41+
IReadOnlyList<string> logLines = loggerProvider.GetLines();
42+
43+
logLines.Should().Contain(
44+
"[DEBUG] Failed to load assembly. To log expression trees, add a NuGet reference to 'AgileObjects.ReadableExpressions' in your project.");
45+
}
46+
47+
private sealed class TestDbContext(DbContextOptions options)
48+
: DbContext(options)
49+
{
50+
public DbSet<PrivateResource> PrivateResources => Set<PrivateResource>();
51+
}
52+
}

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,7 @@ public AtomicTraceLoggingTests(IntegrationTestContext<TestableStartup<Operations
2222
testContext.ConfigureLogging(options =>
2323
{
2424
var loggerProvider = new CapturingLoggerProvider((category, level) =>
25-
level >= LogLevel.Trace && category.StartsWith("JsonApiDotNetCore.", StringComparison.Ordinal));
25+
level == LogLevel.Trace && category.StartsWith("JsonApiDotNetCore.", StringComparison.Ordinal));
2626

2727
options.AddProvider(loggerProvider);
2828
options.SetMinimumLevel(LogLevel.Trace);

‎test/JsonApiDotNetCoreTests/IntegrationTests/Logging/Fruit.cs

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,4 +10,7 @@ public abstract class Fruit : Identifiable<long>
1010
{
1111
[Attr]
1212
public abstract string Color { get; }
13+
14+
[Attr]
15+
public double WeightInKilograms { get; set; }
1316
}

‎test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingFakers.cs

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,10 +15,12 @@ internal sealed class LoggingFakers
1515

1616
private readonly Lazy<Faker<Banana>> _lazyBananaFaker = new(() => new Faker<Banana>()
1717
.MakeDeterministic()
18+
.RuleFor(banana => banana.WeightInKilograms, faker => faker.Random.Double(.2, .3))
1819
.RuleFor(banana => banana.LengthInCentimeters, faker => faker.Random.Double(10, 25)));
1920

2021
private readonly Lazy<Faker<Peach>> _lazyPeachFaker = new(() => new Faker<Peach>()
2122
.MakeDeterministic()
23+
.RuleFor(peach => peach.WeightInKilograms, faker => faker.Random.Double(.2, .3))
2224
.RuleFor(peach => peach.DiameterInCentimeters, faker => faker.Random.Double(6, 7.5)));
2325

2426
public Faker<AuditEntry> AuditEntry => _lazyAuditEntryFaker.Value;

‎test/JsonApiDotNetCoreTests/IntegrationTests/Logging/LoggingTests.cs

Lines changed: 98 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -152,9 +152,9 @@ await _testContext.RunOnDatabaseAsync(async dbContext =>
152152

153153
responseDocument.Should().BeEmpty();
154154

155-
IReadOnlyList<string> logLines = loggerProvider.GetLines();
155+
string[] traceLines = loggerProvider.GetMessages().Where(message => message.LogLevel == LogLevel.Trace).Select(message => message.ToString()).ToArray();
156156

157-
logLines.Should().BeEquivalentTo(new[]
157+
traceLines.Should().BeEquivalentTo(new[]
158158
{
159159
$$"""
160160
[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
215215
{
216216
"Color": "Yellow",
217217
"LengthInCentimeters": {{existingBanana.LengthInCentimeters.ToString(CultureInfo.InvariantCulture)}},
218+
"WeightInKilograms": {{existingBanana.WeightInKilograms.ToString(CultureInfo.InvariantCulture)}},
218219
"Id": {{existingBanana.Id}},
219220
"StringId": "{{existingBanana.StringId}}"
220221
}
@@ -262,9 +263,9 @@ await _testContext.RunOnDatabaseAsync(async dbContext =>
262263

263264
responseDocument.Should().BeEmpty();
264265

265-
IReadOnlyList<string> logLines = loggerProvider.GetLines();
266+
string[] traceLines = loggerProvider.GetMessages().Where(message => message.LogLevel == LogLevel.Trace).Select(message => message.ToString()).ToArray();
266267

267-
logLines.Should().BeEquivalentTo(new[]
268+
traceLines.Should().BeEquivalentTo(new[]
268269
{
269270
$$"""
270271
[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
281282
{
282283
"Color": "Red/Yellow",
283284
"DiameterInCentimeters": 0,
285+
"WeightInKilograms": 0,
284286
"Id": {{existingPeach.Id}},
285287
"StringId": "{{existingPeach.StringId}}"
286288
}
@@ -291,6 +293,7 @@ [TRACE] Entering AddToToManyRelationshipAsync(leftId: {{existingBowl.StringId}},
291293
{
292294
"Color": "Red/Yellow",
293295
"DiameterInCentimeters": 0,
296+
"WeightInKilograms": 0,
294297
"Id": {{existingPeach.Id}},
295298
"StringId": "{{existingPeach.StringId}}"
296299
}
@@ -329,11 +332,102 @@ [TRACE] Entering AddToToManyRelationshipAsync(leftResource: null, leftId: {{exis
329332
{
330333
"Color": "Red/Yellow",
331334
"DiameterInCentimeters": 0,
335+
"WeightInKilograms": 0,
332336
"Id": {{existingPeach.Id}},
333337
"StringId": "{{existingPeach.StringId}}"
334338
}
335339
])
336340
"""
337341
}, options => options.Using(IgnoreLineEndingsComparer.Instance).WithStrictOrdering());
338342
}
343+
344+
[Fact]
345+
public async Task Logs_query_layer_and_expression_at_Debug_level()
346+
{
347+
// Arrange
348+
var loggerProvider = _testContext.Factory.Services.GetRequiredService<CapturingLoggerProvider>();
349+
loggerProvider.Clear();
350+
351+
var bowl = new FruitBowl();
352+
bowl.Fruits.Add(_fakers.Peach.GenerateOne());
353+
354+
await _testContext.RunOnDatabaseAsync(async dbContext =>
355+
{
356+
dbContext.FruitBowls.Add(bowl);
357+
await dbContext.SaveChangesAsync();
358+
});
359+
360+
string route = $"/fruitBowls/{bowl.StringId}/fruits?filter=greaterThan(weightInKilograms,'0.1')&fields[peaches]=color&sort=-id";
361+
362+
// Act
363+
(HttpResponseMessage httpResponse, string responseDocument) = await _testContext.ExecuteGetAsync<string>(route);
364+
365+
// Assert
366+
httpResponse.ShouldHaveStatusCode(HttpStatusCode.OK);
367+
368+
responseDocument.Should().NotBeEmpty();
369+
370+
LogMessage queryLayerMessage = loggerProvider.GetMessages().Should()
371+
.ContainSingle(message => message.LogLevel == LogLevel.Debug && message.Text.StartsWith("QueryLayer:", StringComparison.Ordinal)).Subject;
372+
373+
queryLayerMessage.Text.Should().Be($$"""
374+
QueryLayer: QueryLayer<FruitBowl>
375+
{
376+
Include: fruits
377+
Filter: equals(id,'{{bowl.StringId}}')
378+
Selection
379+
{
380+
FieldSelectors<FruitBowl>
381+
{
382+
id
383+
fruits: QueryLayer<Fruit>
384+
{
385+
Filter: greaterThan(weightInKilograms,'0.1')
386+
Sort: -id
387+
Pagination: Page number: 1, size: 10
388+
Selection
389+
{
390+
FieldSelectors<Peach>
391+
{
392+
color
393+
id
394+
}
395+
}
396+
}
397+
}
398+
}
399+
}
400+
401+
""");
402+
403+
LogMessage expressionMessage = loggerProvider.GetMessages().Should().ContainSingle(message =>
404+
message.LogLevel == LogLevel.Debug && message.Text.StartsWith("Expression tree:", StringComparison.Ordinal)).Subject;
405+
406+
expressionMessage.Text.Should().Be("""
407+
Expression tree: [Microsoft.EntityFrameworkCore.Query.EntityQueryRootExpression]
408+
.AsNoTrackingWithIdentityResolution()
409+
.Include("Fruits")
410+
.Where(fruitBowl => fruitBowl.Id == value)
411+
.Select(
412+
fruitBowl => new FruitBowl
413+
{
414+
Id = fruitBowl.Id,
415+
Fruits = fruitBowl.Fruits
416+
.Where(fruit => fruit.WeightInKilograms > value)
417+
.OrderByDescending(fruit => fruit.Id)
418+
.Take(value)
419+
.Select(
420+
fruit => (fruit.GetType() == value)
421+
? (Fruit)new Peach
422+
{
423+
Id = fruit.Id,
424+
WeightInKilograms = fruit.WeightInKilograms,
425+
DiameterInCentimeters = ((Peach)fruit).DiameterInCentimeters,
426+
Id = fruit.Id
427+
}
428+
: fruit)
429+
.ToHashSet()
430+
})
431+
""");
432+
}
339433
}

0 commit comments

Comments
 (0)