Skip to content

Commit 3a21386

Browse files
KSemenenkoKSemenenko
committed
Fix default command exception logging and release 10.3.15
1 parent ed7ba56 commit 3a21386

5 files changed

Lines changed: 213 additions & 5 deletions

File tree

‎Directory.Build.props‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -27,8 +27,8 @@
2727
<RepositoryUrl>https://github.com/managedcode/Communication</RepositoryUrl>
2828
<PackageProjectUrl>https://github.com/managedcode/Communication</PackageProjectUrl>
2929
<Product>Managed Code - Communication</Product>
30-
<Version>10.3.14</Version>
31-
<PackageVersion>10.3.14</PackageVersion>
30+
<Version>10.3.15</Version>
31+
<PackageVersion>10.3.15</PackageVersion>
3232

3333
</PropertyGroup>
3434
<PropertyGroup Condition="'$(GITHUB_ACTIONS)' == 'true'">

‎ManagedCode.Communication.Tests/Telemetry/TryFailureTelemetryTests.CommandExecution.cs‎

Lines changed: 180 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,180 @@
1+
using System;
2+
using System.Diagnostics;
3+
using System.IO;
4+
using System.Linq;
5+
using System.Text.Json;
6+
using System.Threading;
7+
using System.Threading.Tasks;
8+
using ManagedCode.Communication.Commands;
9+
using ManagedCode.Communication.Commands.Execution;
10+
using ManagedCode.Communication.Logging;
11+
using ManagedCode.Communication.Telemetry;
12+
using Microsoft.Extensions.Logging;
13+
using Microsoft.Extensions.Logging.Abstractions;
14+
using Shouldly;
15+
16+
namespace ManagedCode.Communication.Tests.Telemetry;
17+
18+
public sealed partial class TryFailureTelemetryTests
19+
{
20+
private const int CommandCallerLogger = 3;
21+
22+
[Test]
23+
[Arguments(false, false)]
24+
[Arguments(false, true)]
25+
[Arguments(true, false)]
26+
[Arguments(true, true)]
27+
public async Task CommandExecution_DefaultLogger_ShouldObserveFactoryConfiguredAfterRuntimeConstruction(
28+
bool useValueTask, bool sampleTraces)
29+
{
30+
var previousActivity = Activity.Current;
31+
Activity.Current = null;
32+
try
33+
{
34+
CommunicationLogger.Configure(NullLoggerFactory.Instance);
35+
var runtime = new CommandExecutionRuntime();
36+
using var observation = new Observation(sampleTraces);
37+
var original = new InvalidOperationException(FailureDetail);
38+
Result<int> result;
39+
if (useValueTask)
40+
{
41+
ValueTask<Result<int>> pending = CommandExecutor.ExecuteAsync(Command.Create(CommandExecutionTestConstants.DependencyCall),
42+
(_, _) => ThrowValueTaskAsync(original), runtime);
43+
result = await pending;
44+
}
45+
else
46+
{
47+
Task<Result<int>> pending = CommandExecutor.ExecuteAsync(Command.Create(CommandExecutionTestConstants.DependencyCall),
48+
(_, _) => ThrowTaskAsync(original), runtime);
49+
result = await pending;
50+
}
51+
52+
result.IsFailed.ShouldBeTrue();
53+
result.Problem.StatusCode.ShouldBe((int)System.Net.HttpStatusCode.InternalServerError);
54+
result.Problem.Detail.ShouldBe(FailureDetail);
55+
result.Problem.Extensions.Values.OfType<Exception>().ShouldBeEmpty();
56+
original.StackTrace.ShouldNotBeNullOrWhiteSpace();
57+
original.StackTrace.ShouldContain(nameof(Throw));
58+
JsonSerializer.Serialize(result).ShouldNotContain(original.StackTrace!);
59+
var log = observation.Logs.Single(item => item.Exception is not null);
60+
log.Exception.ShouldBeSameAs(original);
61+
log.Level.ShouldBe(LogLevel.Error);
62+
log.Category.ShouldBe(typeof(Result).FullName);
63+
if (sampleTraces)
64+
{
65+
var span = observation.Spans.ShouldHaveSingleItem();
66+
log.TraceId.ShouldBe(span.TraceId);
67+
log.SpanId.ShouldBe(span.SpanId);
68+
span.Events.Single(item => item.Name == ExceptionEvent).Tags
69+
.Single(item => item.Key == StackTraceTag).Value!.ToString()!.ShouldContain(nameof(Throw));
70+
}
71+
else
72+
{
73+
observation.Spans.ShouldBeEmpty();
74+
}
75+
observation.FlushFailures().ShouldBe(1);
76+
}
77+
finally
78+
{
79+
Activity.Current = previousActivity;
80+
}
81+
}
82+
83+
[Test]
84+
[Arguments(false, ExplicitNullLogger)]
85+
[Arguments(true, ExplicitNullLogger)]
86+
[Arguments(false, DisabledLogger)]
87+
[Arguments(true, DisabledLogger)]
88+
[Arguments(false, CommandCallerLogger)]
89+
[Arguments(true, CommandCallerLogger)]
90+
public async Task CommandExecution_ExplicitLogger_ShouldPreserveCallerAndOptOutPolicy(bool useValueTask, int loggerSelection)
91+
{
92+
using var observation = new Observation();
93+
ILogger logger = loggerSelection switch
94+
{
95+
ExplicitNullLogger => NullLogger.Instance,
96+
DisabledLogger => observation.DisabledLogger,
97+
CommandCallerLogger => observation.Logger,
98+
_ => throw new ArgumentOutOfRangeException(nameof(loggerSelection))
99+
};
100+
var runtime = new CommandExecutionRuntime(logger: logger);
101+
var original = new InvalidOperationException(FailureDetail);
102+
var result = useValueTask
103+
? await CommandExecutor.ExecuteAsync(Command.Create(CommandExecutionTestConstants.DependencyCall),
104+
(_, _) => ThrowValueTaskAsync(original), runtime)
105+
: await CommandExecutor.ExecuteAsync(Command.Create(CommandExecutionTestConstants.DependencyCall),
106+
(_, _) => ThrowTaskAsync(original), runtime);
107+
108+
result.IsFailed.ShouldBeTrue();
109+
if (loggerSelection == CommandCallerLogger)
110+
{
111+
var log = observation.Logs.Single(item => item.Exception is not null);
112+
log.Category.ShouldBe(CallerCategory);
113+
log.Level.ShouldBe(LogLevel.Error);
114+
log.Exception.ShouldBeSameAs(original);
115+
}
116+
else
117+
{
118+
observation.Logs.Where(item => item.Exception is not null).ShouldBeEmpty();
119+
}
120+
var span = observation.Spans.ShouldHaveSingleItem();
121+
span.Events.Single(item => item.Name == ExceptionEvent).Tags
122+
.Single(item => item.Key == StackTraceTag).Value!.ToString()!.ShouldContain(nameof(Throw));
123+
observation.FlushFailures().ShouldBe(1);
124+
}
125+
126+
[Test]
127+
public async Task CommandExecution_DefaultLogger_ShouldObserveOriginalAttemptAndCallbackWithoutChangingSuccess()
128+
{
129+
using var observation = new Observation();
130+
var original = new IOException(FailureDetail);
131+
var observerFailure = new InvalidOperationException(CommandExecutionTestConstants.ObserverFailed);
132+
var options = new CommandExecutionOptions();
133+
options.Retry.Enabled = true;
134+
options.Retry.MaxRetries = 1;
135+
options.Retry.Delay = TimeSpan.Zero;
136+
options.Retry.UseJitter = false;
137+
options.Retry.OnRetry = (_, _) =>
138+
{
139+
Throw(observerFailure);
140+
return ValueTask.CompletedTask;
141+
};
142+
var runtime = new CommandExecutionRuntime(options);
143+
var attempts = 0;
144+
var result = await CommandExecutor.ExecuteAsync(Command.Create(CommandExecutionTestConstants.RetryCallback),
145+
async (_, _) => ++attempts == 1 ? await ThrowTaskAsync(original) : Value, runtime);
146+
147+
result.IsSuccess.ShouldBeTrue();
148+
result.Value.ShouldBe(Value);
149+
attempts.ShouldBe(2);
150+
var exceptions = observation.Logs.Where(item => item.Exception is not null).ToArray();
151+
exceptions.Length.ShouldBe(2);
152+
exceptions.Single(item => ReferenceEquals(item.Exception, original)).Level.ShouldBe(LogLevel.Error);
153+
exceptions.Single(item => ReferenceEquals(item.Exception, observerFailure)).Level.ShouldBe(LogLevel.Error);
154+
original.StackTrace.ShouldNotBeNullOrWhiteSpace();
155+
observerFailure.StackTrace.ShouldNotBeNullOrWhiteSpace();
156+
var span = observation.Spans.ShouldHaveSingleItem();
157+
span.Events.Count(item => item.Name == ExceptionEvent).ShouldBe(2);
158+
observation.FlushFailures().ShouldBe(1);
159+
}
160+
161+
[Test]
162+
public async Task CommandExecution_DefaultLogger_ShouldPreserveCallerCancellationWithoutFailureDiagnostics()
163+
{
164+
using var observation = new Observation();
165+
using var cancellation = new CancellationTokenSource();
166+
var original = new OperationCanceledException(cancellation.Token);
167+
var runtime = new CommandExecutionRuntime();
168+
var observed = await Should.ThrowAsync<OperationCanceledException>(() =>
169+
CommandExecutor.ExecuteAsync(Command.Create(CommandExecutionTestConstants.DependencyCall), (_, _) =>
170+
{
171+
cancellation.Cancel();
172+
return Task.FromException<int>(original);
173+
}, runtime, cancellation.Token));
174+
175+
observed.CancellationToken.ShouldBe(cancellation.Token);
176+
observation.Logs.ShouldBeEmpty();
177+
observation.Spans.ShouldHaveSingleItem().Events.Where(item => item.Name == ExceptionEvent).ShouldBeEmpty();
178+
observation.FlushFailures().ShouldBe(0);
179+
}
180+
}

‎ManagedCode.Communication.Tests/Telemetry/TryFailureTelemetryTests.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,7 @@
2222
namespace ManagedCode.Communication.Tests.Telemetry;
2323

2424
[NotInParallel]
25-
public sealed class TryFailureTelemetryTests
25+
public sealed partial class TryFailureTelemetryTests
2626
{
2727
private const string OperationName = "try-failure-operation";
2828
private const string CallerCategory = "try-failure-caller";

‎ManagedCode.Communication/Commands/Execution/CommandExecutionRuntime.cs‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
using System;
2+
using ManagedCode.Communication.Logging;
23
using Microsoft.Extensions.Logging;
34

45
namespace ManagedCode.Communication.Commands.Execution;
@@ -9,6 +10,7 @@ namespace ManagedCode.Communication.Commands.Execution;
910
public sealed class CommandExecutionRuntime
1011
{
1112
private readonly CommandExecutionOptions _optionsSnapshot;
13+
private readonly ILogger? _logger;
1214

1315
/// <summary>
1416
/// Creates a command execution runtime.
@@ -27,7 +29,7 @@ public CommandExecutionRuntime(
2729
IdempotencyStore = idempotencyStore;
2830
RateLimiter = rateLimiter;
2931
TimeProvider = timeProvider ?? TimeProvider.System;
30-
Logger = logger;
32+
_logger = logger;
3133
CircuitBreaker = circuitBreaker ?? (_optionsSnapshot.CircuitBreaker.Enabled
3234
? new PartitionedCommandCircuitBreaker(_optionsSnapshot.CircuitBreaker, TimeProvider)
3335
: null);
@@ -53,5 +55,9 @@ public CommandExecutionRuntime(
5355
public TimeProvider TimeProvider { get; }
5456

5557
/// <summary>Logger for original command exceptions, or safe metadata for HTTP operations.</summary>
56-
public ILogger? Logger { get; }
58+
/// <remarks>
59+
/// An omitted logger resolves the currently configured Communication logger when diagnostics are emitted.
60+
/// An explicitly supplied logger, including a disabled logger, is always preserved.
61+
/// </remarks>
62+
public ILogger? Logger => _logger ?? CommunicationLogger.GetLogger();
5763
}

‎README.md‎

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -695,6 +695,28 @@ Task handlers produce Task results and ValueTask handlers produce ValueTask resu
695695
also supported. Without DI, use `CommandExecutionRuntime` with static `CommandExecutor.ExecuteAsync` or
696696
`Result<T>.ExecuteAsync` entry points.
697697

698+
A runtime without an explicit logger resolves the currently configured Communication logger at each diagnostic
699+
boundary. It can be created before the host configures its logger factory:
700+
701+
```csharp
702+
using ManagedCode.Communication.Logging;
703+
using Microsoft.Extensions.Logging.Abstractions;
704+
705+
var runtime = new CommandExecutionRuntime(executionOptions);
706+
CommunicationLogger.Configure(loggerFactory);
707+
708+
Result<Catalog> result = await CommandExecutor.ExecuteAsync(
709+
Command.Create("catalog.refresh"),
710+
(_, token) => catalogService.RefreshAsync(sourceId, token),
711+
runtime,
712+
cancellationToken);
713+
```
714+
715+
An explicit caller logger always takes precedence. Pass `NullLogger.Instance` to the runtime to suppress its
716+
original-exception log output while retaining telemetry; a disabled explicit logger is also respected. This
717+
runtime default does not change explicit `CommunicationDiagnostics.ReportFailure(null, ...)`, which remains
718+
telemetry-only.
719+
698720
### Retry decisions and delays
699721

700722
`MaxRetries` counts retries after the first attempt: `3` allows up to four physical attempts. Execution stops

0 commit comments

Comments
 (0)