Skip to content

Commit 3dcb39b

Browse files
Copilotmauroservienti
Copilot
and
mauroservienti
authored
Strengthen structured logging for composition/scatter-gather fallback paths (#1018)
* Improve response serialization warning to structured logging Co-authored-by: mauroservienti <1325611+mauroservienti@users.noreply.github.com> * Add warning log when downstream gatherer errors are ignored Co-authored-by: mauroservienti <1325611+mauroservienti@users.noreply.github.com> * Refine gatherer logging test assertions and logger reuse Co-authored-by: mauroservienti <1325611+mauroservienti@users.noreply.github.com> * Remove accidental test output artifact Co-authored-by: mauroservienti <1325611+mauroservienti@users.noreply.github.com> * Revert unrelated nullability changes in HttpGatherer Co-authored-by: mauroservienti <1325611+mauroservienti@users.noreply.github.com> * Add logging for composition failures * Simpler pattern * Add logging for invalid casing * Add logging when mapping scatter/gatther routes * Log components count in MapCompositionHandlers / MapGetComponents and MapPostComponents * formatting * log how many components in the registry * Add an optional logger to the scanner * test * basic composition over controllers logging * Some logging when raising events * Log composition requests * improve assert --------- Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com> Co-authored-by: mauroservienti <1325611+mauroservienti@users.noreply.github.com> Co-authored-by: Mauro Servienti <mauro.servienti@gmail.com>
1 parent 1823357 commit 3dcb39b

18 files changed

Lines changed: 705 additions & 22 deletions

‎src/ServiceComposer.AspNetCore.Tests/ResponseSerializationOptions_validate_configuration.cs‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,8 @@ public async Task Logs_warning_when_using_invalid_config()
2727

2828
var log = Assert.Single(loggerFactory.Sink.LogEntries);
2929
Assert.Equal(LogLevel.Warning, log.LogLevel);
30+
Assert.Equal("ResponseSerialization {UseOutputFormatters} is set to true, and it's also configured to use either a custom response casing or custom json serializer settings. When using output formatters, custom settings are ignored", log.OriginalFormat);
31+
Assert.Contains(log.Properties, p => p.Key == "UseOutputFormatters" && (string)p.Value == nameof(ResponseSerializationOptions.UseOutputFormatters));
3032

3133
await Verifier.Verify(log.Message);
3234
}
@@ -99,4 +101,4 @@ public void Logs_nothing_when_using_valid_config_with_formatters()
99101
Assert.Empty(loggerFactory.Sink.LogEntries.ToList());
100102
}
101103
}
102-
}
104+
}

‎src/ServiceComposer.AspNetCore.Tests/ScatterGather/When_downstream_returns_error.cs‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,9 +3,11 @@
33
using System.Net;
44
using System.Net.Http;
55
using System.Threading.Tasks;
6+
using MELT;
67
using Microsoft.AspNetCore.Builder;
78
using Microsoft.Extensions.DependencyInjection;
89
using Microsoft.Extensions.DependencyInjection.Extensions;
10+
using Microsoft.Extensions.Logging;
911
using ServiceComposer.AspNetCore.Testing;
1012
using ServiceComposer.AspNetCore.Tests.Utils;
1113
using Xunit;
@@ -138,12 +140,14 @@ public async Task IgnoreDownstreamRequestErrors_returns_empty_array_when_all_gat
138140
{
139141
// Arrange
140142
var failingClient = BuildDownstreamClientReturning(HttpStatusCode.InternalServerError);
143+
var loggerFactory = TestLoggerFactory.Create(options => options.FilterByTypeName<HttpGatherer>());
141144

142145
var client = new SelfContainedWebApplicationFactoryWithWebHost<Dummy>
143146
(
144147
configureServices: services =>
145148
{
146149
services.AddRouting();
150+
services.Replace(ServiceDescriptor.Singleton<ILoggerFactory>(loggerFactory));
147151
services.Replace(new ServiceDescriptor(typeof(IHttpClientFactory),
148152
new DelegateHttpClientFactory(_ => failingClient)));
149153
},
@@ -171,5 +175,13 @@ public async Task IgnoreDownstreamRequestErrors_returns_empty_array_when_all_gat
171175
var body = await response.Content.ReadAsStringAsync();
172176
var array = System.Text.Json.Nodes.JsonNode.Parse(body)!.AsArray();
173177
Assert.Empty(array);
178+
179+
var log = Assert.Single(loggerFactory.Sink.LogEntries);
180+
Assert.Equal("Ignoring downstream request error for gatherer {GathererKey} at {DestinationUrl}.", log.OriginalFormat);
181+
Assert.Equal(LogLevel.Warning, log.LogLevel);
182+
var gathererKey = Assert.Single(log.Properties, p => p.Key == "GathererKey").Value;
183+
var destinationUrl = Assert.Single(log.Properties, p => p.Key == "DestinationUrl").Value;
184+
Assert.Equal("Source", gathererKey);
185+
Assert.Equal("/upstream/source", destinationUrl);
174186
}
175187
}

‎src/ServiceComposer.AspNetCore.Tests/ScatterGather/When_scatter_gather_logs.cs‎

Lines changed: 104 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,104 @@
1+
using System.Collections.Generic;
2+
using System.Linq;
3+
using System.Threading.Tasks;
4+
using MELT;
5+
using Microsoft.AspNetCore.Builder;
6+
using Microsoft.AspNetCore.Http;
7+
using Microsoft.Extensions.Configuration;
8+
using Microsoft.Extensions.DependencyInjection;
9+
using Microsoft.Extensions.DependencyInjection.Extensions;
10+
using Microsoft.Extensions.Logging;
11+
using ServiceComposer.AspNetCore.Testing;
12+
using Xunit;
13+
14+
namespace ServiceComposer.AspNetCore.Tests.ScatterGather;
15+
16+
public class When_scatter_gather_logs
17+
{
18+
class FixedGatherer(string key, object[] items) : IGatherer
19+
{
20+
public string Key { get; } = key;
21+
22+
public Task<IEnumerable<object>> Gather(HttpContext context)
23+
=> Task.FromResult<IEnumerable<object>>(items);
24+
}
25+
26+
[Fact]
27+
public async Task Logs_debug_on_execution_with_template_and_gatherer_count()
28+
{
29+
// Arrange
30+
var loggerFactory = TestLoggerFactory.Create(options => options.SetMinimumLevel(LogLevel.Debug));
31+
32+
var client = new SelfContainedWebApplicationFactoryWithWebHost<Dummy>
33+
(
34+
configureServices: services =>
35+
{
36+
services.AddRouting();
37+
services.Replace(ServiceDescriptor.Singleton<ILoggerFactory>(loggerFactory));
38+
},
39+
configure: app =>
40+
{
41+
app.UseRouting();
42+
app.UseEndpoints(builder =>
43+
{
44+
builder.MapScatterGather(template: "/samples", new ScatterGatherOptions
45+
{
46+
Gatherers = new List<IGatherer>
47+
{
48+
new FixedGatherer("Source1", [new { Value = "A" }]),
49+
new FixedGatherer("Source2", [new { Value = "B" }])
50+
}
51+
});
52+
});
53+
}
54+
).CreateClient();
55+
56+
// Act
57+
var response = await client.GetAsync("/samples");
58+
59+
// Assert
60+
Assert.True(response.IsSuccessStatusCode);
61+
62+
// Some ASP.NET Core internal log entries hold lazy references to the now-disposed
63+
// HttpContext, so reading OriginalFormat on them throws ObjectDisposedException.
64+
// The try/catch predicate skips those and finds only our specific entry.
65+
var log = loggerFactory.Sink.LogEntries
66+
.Single(l =>
67+
{
68+
try { return l.OriginalFormat == "Executing scatter-gather for {Template} with {GathererCount} gatherer(s)."; }
69+
catch { return false; }
70+
});
71+
Assert.Equal(LogLevel.Debug, log.LogLevel);
72+
Assert.Equal("/samples", log.Properties.Single(p => p.Key == "Template").Value);
73+
Assert.Equal(2, log.Properties.Single(p => p.Key == "GathererCount").Value);
74+
}
75+
76+
[Fact]
77+
public void Logs_debug_when_configuration_has_no_route_sections()
78+
{
79+
// Arrange
80+
var loggerFactory = TestLoggerFactory.Create(options => options.SetMinimumLevel(LogLevel.Debug));
81+
82+
var emptyConfig = new ConfigurationBuilder().Build();
83+
84+
_ = new SelfContainedWebApplicationFactoryWithWebHost<Dummy>
85+
(
86+
configureServices: services =>
87+
{
88+
services.AddRouting();
89+
services.AddScatterGather();
90+
services.Replace(ServiceDescriptor.Singleton<ILoggerFactory>(loggerFactory));
91+
},
92+
configure: app =>
93+
{
94+
app.UseRouting();
95+
app.UseEndpoints(builder => builder.MapScatterGather(emptyConfig));
96+
}
97+
).CreateClient();
98+
99+
// Assert — log emitted at startup, no HTTP request needed
100+
var log = loggerFactory.Sink.LogEntries
101+
.Single(l => l.OriginalFormat == "No scatter-gather route sections found in configuration. No endpoints will be registered.");
102+
Assert.Equal(LogLevel.Warning, log.LogLevel);
103+
}
104+
}

‎src/ServiceComposer.AspNetCore.Tests/When_composition_fails.cs‎

Lines changed: 63 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,63 @@
1+
using System;
2+
using System.Threading.Tasks;
3+
using MELT;
4+
using Microsoft.AspNetCore.Builder;
5+
using Microsoft.AspNetCore.Http;
6+
using Microsoft.AspNetCore.Mvc;
7+
using Microsoft.Extensions.DependencyInjection;
8+
using Microsoft.Extensions.DependencyInjection.Extensions;
9+
using Microsoft.Extensions.Logging;
10+
using ServiceComposer.AspNetCore.Testing;
11+
using Xunit;
12+
13+
namespace ServiceComposer.AspNetCore.Tests
14+
{
15+
public class When_composition_fails
16+
{
17+
class ThrowingHandler : ICompositionRequestsHandler
18+
{
19+
[HttpGet("/failing/{id}")]
20+
public Task Handle(HttpRequest request)
21+
{
22+
throw new InvalidOperationException("Something went wrong during composition");
23+
}
24+
}
25+
26+
[Fact]
27+
public async Task Logs_error_when_handler_throws()
28+
{
29+
// Arrange
30+
var loggerFactory = TestLoggerFactory.Create(options => options.SetMinimumLevel(LogLevel.Error));
31+
32+
var client = new SelfContainedWebApplicationFactoryWithWebHost<Dummy>
33+
(
34+
configureServices: services =>
35+
{
36+
services.AddViewModelComposition(options =>
37+
{
38+
options.AssemblyScanner.Disable();
39+
options.RegisterCompositionHandler<ThrowingHandler>();
40+
});
41+
services.AddRouting();
42+
services.Replace(ServiceDescriptor.Singleton<ILoggerFactory>(loggerFactory));
43+
},
44+
configure: app =>
45+
{
46+
app.UseRouting();
47+
app.UseEndpoints(builder => builder.MapCompositionHandlers());
48+
}
49+
).CreateClient();
50+
51+
// Act
52+
await Assert.ThrowsAsync<InvalidOperationException>(() => client.GetAsync("/failing/1"));
53+
54+
// Assert
55+
var log = Assert.Single(loggerFactory.Sink.LogEntries);
56+
Assert.Equal(LogLevel.Error, log.LogLevel);
57+
Assert.Equal("Composition failed for request {RequestId}.", log.OriginalFormat);
58+
Assert.Single(log.Properties, p => p.Key == "RequestId");
59+
Assert.NotNull(log.Exception);
60+
Assert.IsType<InvalidOperationException>(log.Exception);
61+
}
62+
}
63+
}

‎src/ServiceComposer.AspNetCore.Tests/When_handling_composition_request_logs.cs‎

Lines changed: 111 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,111 @@
1+
using System.Linq;
2+
using System.Threading.Tasks;
3+
using MELT;
4+
using Microsoft.AspNetCore.Builder;
5+
using Microsoft.AspNetCore.Http;
6+
using Microsoft.AspNetCore.Mvc;
7+
using Microsoft.Extensions.DependencyInjection;
8+
using Microsoft.Extensions.DependencyInjection.Extensions;
9+
using Microsoft.Extensions.Logging;
10+
using ServiceComposer.AspNetCore.Testing;
11+
using Xunit;
12+
13+
namespace ServiceComposer.AspNetCore.Tests
14+
{
15+
public class When_handling_composition_request_logs
16+
{
17+
class TestGetHandler : ICompositionRequestsHandler
18+
{
19+
[HttpGet("/api/sample/{id}")]
20+
public Task Handle(HttpRequest request) => Task.CompletedTask;
21+
}
22+
23+
class TestPostHandler : ICompositionRequestsHandler
24+
{
25+
[HttpPost("/api/sample/{id}")]
26+
public Task Handle(HttpRequest request) => Task.CompletedTask;
27+
}
28+
29+
[Fact]
30+
public async Task Logs_debug_on_get_request()
31+
{
32+
// Arrange
33+
var loggerFactory = TestLoggerFactory.Create(options => options.SetMinimumLevel(LogLevel.Debug));
34+
35+
var client = new SelfContainedWebApplicationFactoryWithWebHost<Dummy>
36+
(
37+
configureServices: services =>
38+
{
39+
services.AddViewModelComposition(options =>
40+
{
41+
options.AssemblyScanner.Disable();
42+
options.RegisterCompositionHandler<TestGetHandler>();
43+
});
44+
services.AddRouting();
45+
services.Replace(ServiceDescriptor.Singleton<ILoggerFactory>(loggerFactory));
46+
},
47+
configure: app =>
48+
{
49+
app.UseRouting();
50+
app.UseEndpoints(builder => builder.MapCompositionHandlers());
51+
}
52+
).CreateClient();
53+
54+
// Act
55+
await client.GetAsync("/api/sample/1");
56+
57+
// Assert
58+
var log = loggerFactory.Sink.LogEntries
59+
.Single(l =>
60+
{
61+
try { return l.OriginalFormat == "Handling composition request at {Method} {Template} with {HandlerCount} handler(s)."; }
62+
catch { return false; }
63+
});
64+
Assert.Equal(LogLevel.Debug, log.LogLevel);
65+
Assert.Equal("GET", log.Properties.Single(p => p.Key == "Method").Value);
66+
Assert.Equal("api/sample/{id}", log.Properties.Single(p => p.Key == "Template").Value);
67+
Assert.Equal(1, log.Properties.Single(p => p.Key == "HandlerCount").Value);
68+
}
69+
70+
[Fact]
71+
public async Task Logs_debug_on_post_request()
72+
{
73+
// Arrange
74+
var loggerFactory = TestLoggerFactory.Create(options => options.SetMinimumLevel(LogLevel.Debug));
75+
76+
var client = new SelfContainedWebApplicationFactoryWithWebHost<Dummy>
77+
(
78+
configureServices: services =>
79+
{
80+
services.AddViewModelComposition(options =>
81+
{
82+
options.AssemblyScanner.Disable();
83+
options.RegisterCompositionHandler<TestPostHandler>();
84+
});
85+
services.AddRouting();
86+
services.Replace(ServiceDescriptor.Singleton<ILoggerFactory>(loggerFactory));
87+
},
88+
configure: app =>
89+
{
90+
app.UseRouting();
91+
app.UseEndpoints(builder => builder.MapCompositionHandlers());
92+
}
93+
).CreateClient();
94+
95+
// Act
96+
await client.PostAsync("/api/sample/1", content: null);
97+
98+
// Assert
99+
var log = loggerFactory.Sink.LogEntries
100+
.Single(l =>
101+
{
102+
try { return l.OriginalFormat == "Handling composition request at {Method} {Template} with {HandlerCount} handler(s)."; }
103+
catch { return false; }
104+
});
105+
Assert.Equal(LogLevel.Debug, log.LogLevel);
106+
Assert.Equal("POST", log.Properties.Single(p => p.Key == "Method").Value);
107+
Assert.Equal("api/sample/{id}", log.Properties.Single(p => p.Key == "Template").Value);
108+
Assert.Equal(1, log.Properties.Single(p => p.Key == "HandlerCount").Value);
109+
}
110+
}
111+
}

0 commit comments

Comments
 (0)