Skip to content

Commit ed7ba56

Browse files
KSemenenkoKSemenenko
committed
fix: preserve delayed original failure diagnostics
1 parent 313bb38 commit ed7ba56

5 files changed

Lines changed: 258 additions & 18 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.13</Version>
31-
<PackageVersion>10.3.13</PackageVersion>
30+
<Version>10.3.14</Version>
31+
<PackageVersion>10.3.14</PackageVersion>
3232

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

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

Lines changed: 210 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ public sealed class TryFailureTelemetryTests
2626
{
2727
private const string OperationName = "try-failure-operation";
2828
private const string CallerCategory = "try-failure-caller";
29+
private const string DisabledCallerCategory = "disabled-try-failure-caller";
2930
private const string FailureDetail = "original failure detail";
3031
private const string BusinessTitle = "Access denied";
3132
private const string BusinessDetail = "The requested Company cannot be accessed.";
@@ -37,6 +38,12 @@ public sealed class TryFailureTelemetryTests
3738
private const string StackTraceTag = "exception.stacktrace";
3839
private const string SensitiveHttpDetail = "secret-http-payload";
3940
private const int Value = 42;
41+
private const int ExplicitNullLogger = 0;
42+
private const int DisabledLogger = 1;
43+
private const int DefaultNullLogger = 2;
44+
private const int AbsentActivity = 0;
45+
private const int SampledActivity = 1;
46+
private const int UnsampledActivity = 2;
4047

4148
[Test]
4249
[Arguments(false)]
@@ -351,6 +358,188 @@ public async Task TryAsync_Success_ShouldPreserveShapeAndInvokeNoProblemFactory(
351358
observation.FlushFailures().ShouldBe(0);
352359
}
353360

361+
[Test]
362+
[Arguments(false, ExplicitNullLogger)]
363+
[Arguments(true, ExplicitNullLogger)]
364+
[Arguments(false, DisabledLogger)]
365+
[Arguments(true, DisabledLogger)]
366+
[Arguments(false, DefaultNullLogger)]
367+
[Arguments(true, DefaultNullLogger)]
368+
public async Task TryAsync_AfterUnavailableLogger_ShouldExportOriginalExceptionOnce(bool useValueTask, int loggerSelection)
369+
{
370+
using var observation = new Observation();
371+
ILogger? unavailableLogger = loggerSelection switch
372+
{
373+
ExplicitNullLogger => NullLogger.Instance,
374+
DisabledLogger => observation.DisabledLogger,
375+
DefaultNullLogger => null,
376+
_ => throw new ArgumentOutOfRangeException(nameof(loggerSelection))
377+
};
378+
if (loggerSelection == DefaultNullLogger)
379+
{
380+
CommunicationLogger.Configure(NullLoggerFactory.Instance);
381+
CommunicationLogger.GetLogger().IsEnabled(LogLevel.Error).ShouldBeFalse();
382+
}
383+
else
384+
{
385+
unavailableLogger.ShouldNotBeNull();
386+
unavailableLogger.IsEnabled(LogLevel.Error).ShouldBeFalse();
387+
}
388+
using (var activity = CommunicationTelemetry.StartActivity(OperationName))
389+
{
390+
activity.ShouldNotBeNull();
391+
var exception = new InvalidOperationException(FailureDetail);
392+
var problem = CreateBusinessProblem();
393+
var first = useValueTask
394+
? await Result.TryAsync((Func<ValueTask<int>>)(() => ThrowValueTaskAsync(exception)), unavailableLogger, problemFactory: _ => problem)
395+
: await Result.TryAsync((Func<Task<int>>)(() => ThrowTaskAsync(exception)), unavailableLogger, problemFactory: _ => problem);
396+
first.IsFailed.ShouldBeTrue();
397+
first.Problem.ShouldBeSameAs(problem);
398+
observation.Logs.ShouldBeEmpty();
399+
activity.Events.Count(item => item.Name == ExceptionEvent).ShouldBe(1);
400+
401+
AssertForwardedFailure(problem, exception, observation.Logger);
402+
AssertException(observation, activity, exception);
403+
AssertBusinessProblem(problem);
404+
activity.Status.ShouldBe(ActivityStatusCode.Unset);
405+
}
406+
407+
observation.Spans.ShouldHaveSingleItem().Events.Count(item => item.Name == ExceptionEvent).ShouldBe(1);
408+
observation.FlushFailures().ShouldBe(1);
409+
observation.CreatedErrorTypes.ShouldHaveSingleItem().ShouldBe(nameof(InvalidOperationException));
410+
}
411+
412+
[Test]
413+
[Arguments(false, false)]
414+
[Arguments(false, true)]
415+
[Arguments(true, false)]
416+
[Arguments(true, true)]
417+
public async Task TryAsync_WithoutInitialActivity_ShouldExportLaterOriginalTraceOnce(bool useValueTask, bool initialLoggerEnabled)
418+
{
419+
using var observation = new Observation();
420+
var previousActivity = Activity.Current;
421+
Activity.Current = null;
422+
try
423+
{
424+
var exception = new InvalidOperationException(FailureDetail);
425+
var problem = CreateBusinessProblem();
426+
var logger = initialLoggerEnabled ? observation.Logger : NullLogger.Instance;
427+
var first = useValueTask
428+
? await Result.TryAsync((Func<ValueTask<int>>)(() => ThrowValueTaskAsync(exception)), logger, problemFactory: _ => problem)
429+
: await Result.TryAsync((Func<Task<int>>)(() => ThrowTaskAsync(exception)), logger, problemFactory: _ => problem);
430+
first.IsFailed.ShouldBeTrue();
431+
first.Problem.ShouldBeSameAs(problem);
432+
observation.Logs.Count.ShouldBe(initialLoggerEnabled ? 1 : 0);
433+
observation.Spans.ShouldBeEmpty();
434+
using (var activity = CommunicationTelemetry.StartActivity(OperationName))
435+
{
436+
activity.ShouldNotBeNull();
437+
AssertForwardedFailure(problem, exception, observation.Logger);
438+
var log = observation.Logs.ShouldHaveSingleItem();
439+
log.Level.ShouldBe(LogLevel.Error);
440+
log.Exception.ShouldBeSameAs(exception);
441+
log.TraceId.ShouldBe(initialLoggerEnabled ? default : activity.TraceId);
442+
log.SpanId.ShouldBe(initialLoggerEnabled ? default : activity.SpanId);
443+
var trace = activity.Events.Single(item => item.Name == ExceptionEvent);
444+
trace.Tags.Single(item => item.Key == StackTraceTag).Value!.ToString()!.ShouldContain(nameof(Throw));
445+
activity.Events.Count(item => item.Name == CommunicationTelemetry.CreatedFailureEventName).ShouldBe(0);
446+
activity.Status.ShouldBe(ActivityStatusCode.Unset);
447+
AssertBusinessProblem(problem);
448+
}
449+
observation.Spans.ShouldHaveSingleItem().Events.Count(item => item.Name == ExceptionEvent).ShouldBe(1);
450+
observation.FlushFailures().ShouldBe(1);
451+
observation.CreatedErrorTypes.ShouldHaveSingleItem().ShouldBe(nameof(InvalidOperationException));
452+
}
453+
finally
454+
{
455+
Activity.Current = previousActivity;
456+
}
457+
}
458+
459+
[Test]
460+
[Arguments(AbsentActivity)]
461+
[Arguments(SampledActivity)]
462+
[Arguments(UnsampledActivity)]
463+
public async Task TryAsync_AfterUnavailableHttpLogger_ShouldExportOnlySafeOriginalDiagnostics(int activitySelection)
464+
{
465+
using var observation = new Observation(sampleTraces: activitySelection != UnsampledActivity);
466+
var previousActivity = Activity.Current;
467+
Activity.Current = null;
468+
try
469+
{
470+
using var activity = activitySelection == AbsentActivity ? null : CommunicationTelemetry.StartActivity(OperationName);
471+
if (activitySelection != AbsentActivity)
472+
{
473+
activity.ShouldNotBeNull();
474+
activity.Recorded.ShouldBe(activitySelection == SampledActivity);
475+
}
476+
using var privacy = HttpFailureDiagnostics.Begin(true);
477+
var exception = new InvalidOperationException(SensitiveHttpDetail, new FormatException(SensitiveHttpDetail));
478+
var problem = CreateBusinessProblem();
479+
var first = await Result.TryAsync((Func<Task<int>>)(() => ThrowTaskAsync(exception)), NullLogger.Instance, problemFactory: _ => problem);
480+
first.IsFailed.ShouldBeTrue();
481+
first.Problem.ShouldBeSameAs(problem);
482+
observation.Logs.ShouldBeEmpty();
483+
AssertForwardedFailure(problem, exception, observation.Logger);
484+
var log = observation.Logs.ShouldHaveSingleItem();
485+
log.Level.ShouldBe(LogLevel.Error);
486+
log.Exception.ShouldBeNull();
487+
log.Message.ShouldContain(nameof(InvalidOperationException));
488+
log.Message.ShouldContain(nameof(FormatException));
489+
log.Message.ShouldContain(nameof(Throw));
490+
log.Message.ShouldNotContain(SensitiveHttpDetail);
491+
log.Message.ShouldNotContain(BusinessDetail);
492+
if (activity is not null)
493+
{
494+
var trace = activity.Events.Single(item => item.Name == ExceptionEvent);
495+
trace.Tags.Single(item => item.Key == StackTraceTag).Value!.ToString()!.ShouldContain(nameof(Throw));
496+
foreach (var tag in activity.Events.SelectMany(item => item.Tags))
497+
{
498+
tag.Value?.ToString()?.ShouldNotContain(SensitiveHttpDetail);
499+
tag.Value?.ToString()?.ShouldNotContain(BusinessDetail);
500+
}
501+
activity.Status.ShouldBe(ActivityStatusCode.Unset);
502+
}
503+
observation.FlushFailures().ShouldBe(1);
504+
observation.CreatedErrorTypes.ShouldHaveSingleItem().ShouldBe(nameof(InvalidOperationException));
505+
}
506+
finally
507+
{
508+
Activity.Current = previousActivity;
509+
}
510+
}
511+
512+
private static Problem CreateBusinessProblem()
513+
{
514+
var problem = Problem.Create(BusinessTitle, BusinessDetail, HttpStatusCode.Forbidden);
515+
problem.ErrorCode = BusinessCode;
516+
problem.Instance = BusinessInstance;
517+
problem.Extensions[BusinessExtension] = BusinessOwner;
518+
return problem;
519+
}
520+
521+
private static void AssertBusinessProblem(Problem problem)
522+
{
523+
problem.StatusCode.ShouldBe((int)HttpStatusCode.Forbidden);
524+
problem.ErrorCode.ShouldBe(BusinessCode);
525+
problem.Title.ShouldBe(BusinessTitle);
526+
problem.Detail.ShouldBe(BusinessDetail);
527+
problem.Instance.ShouldBe(BusinessInstance);
528+
problem.Extensions[BusinessExtension].ShouldBe(BusinessOwner);
529+
problem.Extensions.Values.OfType<Exception>().ShouldBeEmpty();
530+
}
531+
532+
private static void AssertForwardedFailure(Problem problem, Exception exception, ILogger logger)
533+
{
534+
var result = Result<int>.Fail(exception, logger, problemFactory: _ => problem);
535+
result.IsFailed.ShouldBeTrue();
536+
result.Problem.ShouldBeSameAs(problem);
537+
Result.Fail(exception, logger, problemFactory: _ => problem).Problem.ShouldBeSameAs(problem);
538+
CollectionResult<int>.Fail(exception, logger, problemFactory: _ => problem).Problem.ShouldBeSameAs(problem);
539+
Result.Fail(problem).Problem.ShouldBeSameAs(problem);
540+
JsonSerializer.Serialize(result).ShouldNotContain(exception.StackTrace!);
541+
}
542+
354543
private static void AssertException(Observation observation, Activity activity, Exception exception)
355544
{
356545
var log = observation.Logs.ShouldHaveSingleItem();
@@ -416,20 +605,27 @@ private sealed class Observation : IDisposable
416605
private readonly MeterProvider _meter;
417606
private long _failures;
418607

419-
internal Observation()
608+
internal Observation(bool sampleTraces = true)
420609
{
421-
_factory = LoggerFactory.Create(builder => builder.AddOpenTelemetry(options =>
610+
_factory = LoggerFactory.Create(builder => builder
611+
.AddFilter(DisabledCallerCategory, LogLevel.Critical)
612+
.AddOpenTelemetry(options =>
422613
{
423614
options.IncludeFormattedMessage = true;
424615
options.AddProcessor(new SimpleLogRecordExportProcessor(new CaptureExporter<LogRecord>(record =>
425616
Logs.Add(new LogEntry(record.LogLevel, record.Exception, record.CategoryName, record.TraceId, record.SpanId, record.FormattedMessage ?? string.Empty)))));
426617
}));
427618
CommunicationLogger.Configure(_factory);
428619
Logger = _factory.CreateLogger(CallerCategory);
429-
_tracer = Sdk.CreateTracerProviderBuilder()
620+
DisabledLogger = _factory.CreateLogger(DisabledCallerCategory);
621+
var tracing = Sdk.CreateTracerProviderBuilder()
430622
.AddSource(CommunicationTelemetry.SourceName)
431-
.AddProcessor(new SimpleActivityExportProcessor(new CaptureExporter<Activity>(Spans.Add)))
432-
.Build();
623+
.AddProcessor(new SimpleActivityExportProcessor(new CaptureExporter<Activity>(Spans.Add)));
624+
if (!sampleTraces)
625+
{
626+
tracing.SetSampler(new AlwaysOffSampler());
627+
}
628+
_tracer = tracing.Build();
433629
_meter = Sdk.CreateMeterProviderBuilder()
434630
.AddMeter(CommunicationTelemetry.SourceName)
435631
.AddReader(new PeriodicExportingMetricReader(new CaptureExporter<Metric>(metric =>
@@ -439,15 +635,24 @@ internal Observation()
439635
foreach (ref readonly var point in metric.GetMetricPoints())
440636
{
441637
_failures += point.GetSumLong();
638+
foreach (var tag in point.Tags)
639+
{
640+
if (tag.Key == CommunicationTelemetry.ErrorTypeTag)
641+
{
642+
CreatedErrorTypes.Add(tag.Value?.ToString());
643+
}
644+
}
442645
}
443646
}
444647
}), exportIntervalMilliseconds: int.MaxValue))
445648
.Build();
446649
}
447650

448651
internal ILogger Logger { get; }
652+
internal ILogger DisabledLogger { get; }
449653
internal List<LogEntry> Logs { get; } = [];
450654
internal List<Activity> Spans { get; } = [];
655+
internal List<string?> CreatedErrorTypes { get; } = [];
451656
internal long FlushFailures()
452657
{
453658
_meter.ForceFlush().ShouldBeTrue();

‎ManagedCode.Communication/Telemetry/CommunicationDiagnostics.cs‎

Lines changed: 24 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -24,25 +24,40 @@ public static class CommunicationDiagnostics
2424
internal static void ReportCreatedFailure(Problem problem, Exception? exception = null, ILogger? logger = null)
2525
{
2626
var state = CreatedFailures.GetValue(problem, static _ => new CreatedFailureState());
27-
var reportException = exception is not null && Interlocked.Exchange(ref state.ExceptionReported, 1) == 0;
27+
var activity = Activity.Current;
28+
var effectiveLogger = logger;
29+
var traceException = exception is not null && activity is not null
30+
&& Interlocked.Exchange(ref state.ExceptionTraced, 1) == 0;
31+
var logException = exception is not null && (effectiveLogger ??= CommunicationLogger.GetLogger()).IsEnabled(LogLevel.Error)
32+
&& Interlocked.Exchange(ref state.ExceptionLogged, 1) == 0;
2833
if (Interlocked.Exchange(ref state.Reported, 1) == 0)
2934
{
30-
CommunicationTelemetry.RecordCreatedFailure(problem, reportException ? exception : null, Activity.Current);
31-
LogFailure(logger ?? CommunicationLogger.GetLogger(), problem, reportException ? exception : null);
35+
CommunicationTelemetry.RecordCreatedFailure(problem, exception, activity, traceException);
36+
if (exception is null || logException)
37+
{
38+
LogFailure(effectiveLogger ?? CommunicationLogger.GetLogger(), problem, exception);
39+
}
3240
}
33-
else if (reportException)
41+
else
3442
{
35-
// A previously returned business problem may later be thrown. Keep its first real stack trace
36-
// without counting the same problem as a second failure or retaining the exception.
37-
HttpFailureDiagnostics.RecordException(Activity.Current, exception!);
38-
LogFailure(logger ?? CommunicationLogger.GetLogger(), problem, exception);
43+
// A missing activity or disabled logger must not consume the other output's first original
44+
// exception. Keep their availability independent without recounting or retaining the cause.
45+
if (traceException)
46+
{
47+
HttpFailureDiagnostics.RecordException(activity, exception!);
48+
}
49+
if (logException)
50+
{
51+
LogFailure(effectiveLogger, problem, exception);
52+
}
3953
}
4054
}
4155

4256
private sealed class CreatedFailureState
4357
{
4458
internal int Reported;
45-
internal int ExceptionReported;
59+
internal int ExceptionTraced;
60+
internal int ExceptionLogged;
4661
}
4762

4863
/// <summary>

‎ManagedCode.Communication/Telemetry/CommunicationTelemetry.cs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -270,7 +270,7 @@ public static void RecordFailure(Problem? problem, Exception? exception = null,
270270
AnnotateFailure(problem, exception, activity ?? Activity.Current);
271271
}
272272

273-
internal static void RecordCreatedFailure(Problem problem, Exception? exception, Activity? activity)
273+
internal static void RecordCreatedFailure(Problem problem, Exception? exception, Activity? activity, bool recordException)
274274
{
275275
problem = HttpFailureDiagnostics.Project(problem);
276276
var errorType = ResolveErrorType(problem, exception);
@@ -293,7 +293,7 @@ internal static void RecordCreatedFailure(Problem problem, Exception? exception,
293293
{ ProblemStatusTag, problem.StatusCode },
294294
{ ProblemErrorCodeTag, problem.ErrorCode }
295295
}));
296-
if (exception is not null)
296+
if (recordException && exception is not null)
297297
{
298298
HttpFailureDiagnostics.RecordException(activity, exception);
299299
}

‎README.md‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1145,6 +1145,26 @@ the original exception and throw-site stack trace. Automatic factory diagnostics
11451145
`Problem` object: wrapping the same instance does not report it as a new occurrence. New problems represent
11461146
new occurrences; successes and reading a result do not emit automatic failure diagnostics.
11471147

1148+
The created-failure count, original exception log and original exception trace are deduplicated independently.
1149+
An unavailable activity or Error-disabled logger does not consume the other output's opportunity. If a later
1150+
boundary supplies the same original exception and Problem with an enabled logger or a current activity, that
1151+
output records its first original diagnostic without recounting the problem or repeating an existing output:
1152+
1153+
```csharp
1154+
using Microsoft.Extensions.Logging.Abstractions;
1155+
1156+
Result ObserveOriginalFailure(Exception original, ILogger logger)
1157+
{
1158+
var problem = Problem.Create(original);
1159+
Result.Fail(original, NullLogger.Instance, problemFactory: _ => problem);
1160+
return Result.Fail(original, logger, problemFactory: _ => problem);
1161+
}
1162+
```
1163+
1164+
This requires supplying the original exception again; wrapping the Problem alone cannot recover its stack.
1165+
The library does not retain exceptions or retry exporter delivery. An enabled native logger call and a current
1166+
activity do not guarantee that the application's configured exporters persist their output.
1167+
11481168
HTTP resilience, HTTP-to-Result conversion and HTTP CQRS readers share a privacy boundary. Its automatic failure logs and traces retain status, exception types,
11491169
throw-site stack frames and correlation, while omitting exception messages, inner messages, response reason
11501170
phrases/content and request URL user information/path/query. This policy also applies without sampled traces;

0 commit comments

Comments
 (0)