Skip to content

Commit dee3d1f

Browse files
committed
Move ApplyInboundActivity earlier so dispatch traces have activity IDs
ApplyInboundActivity was called in DispatchRequestAsync, but the RequestReceived and LocalInvocation traces fire earlier in HandleRpcAsync and DispatchIncomingRequestAsync. This meant all server-side dispatch traces had Guid.Empty as their activity ID, breaking cross-process correlation. Move ApplyInboundActivity to HandleRpcAsync before the RequestReceived trace, and dispose the ActivityState in a finally block there. Remove the redundant call from DispatchRequestAsync (the activity is already set on the thread). Add EventsWithActivityIds to CollectingTraceListener and a test that verifies server dispatch traces have the expected activity IDs when CorrelationManagerTracingStrategy is configured.
1 parent f0f18ce commit dee3d1f

3 files changed

Lines changed: 85 additions & 1 deletion

File tree

src/StreamJsonRpc/JsonRpc.cs

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1903,7 +1903,6 @@ protected virtual async ValueTask<JsonRpcMessage> DispatchRequestAsync(JsonRpcRe
19031903
Requires.NotNull(targetMethod);
19041904

19051905
object? result;
1906-
using IDisposable? activityTracingState = this.ActivityTracingStrategy?.ApplyInboundActivity(request);
19071906

19081907
try
19091908
{
@@ -2807,10 +2806,17 @@ private async Task HandleRpcAsync(JsonRpcMessage rpc)
28072806
{
28082807
Requires.NotNull(rpc, nameof(rpc));
28092808
OutstandingCallData? data = null;
2809+
IDisposable? activityTracingState = null;
28102810
try
28112811
{
28122812
if (rpc is JsonRpcRequest request)
28132813
{
2814+
// Set up activity tracing before any dispatch-related traces so that
2815+
// RequestReceived, LocalInvocation, and other server-side trace events
2816+
// are emitted under the correct activity ID for cross-process correlation
2817+
// in tools like SvcTraceViewer.
2818+
activityTracingState = this.ActivityTracingStrategy?.ApplyInboundActivity(request);
2819+
28142820
if (this.TraceSource.Switch.ShouldTrace(TraceEventType.Information))
28152821
{
28162822
if (request.IsResponseExpected)
@@ -2971,6 +2977,10 @@ private async Task HandleRpcAsync(JsonRpcMessage rpc)
29712977
// If we extracted this callback from the collection already, take care to complete it to avoid hanging our client.
29722978
data?.CompletionHandler(null);
29732979
}
2980+
finally
2981+
{
2982+
activityTracingState?.Dispose();
2983+
}
29742984
}
29752985

29762986
private void FaultPendingRequests()

test/StreamJsonRpc.Tests/CollectingTraceListener.cs

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,8 @@ public class CollectingTraceListener : TraceListener
1717

1818
private readonly ImmutableList<(Guid RelatedActivityId, Guid CurrentActivityId)>.Builder transfers = ImmutableList.CreateBuilder<(Guid RelatedActivityId, Guid CurrentActivityId)>();
1919

20+
private readonly ImmutableList<(JsonRpc.TraceEvents TraceEventId, Guid ActivityId)>.Builder eventsWithActivityIds = ImmutableList.CreateBuilder<(JsonRpc.TraceEvents TraceEventId, Guid ActivityId)>();
21+
2022
public override bool IsThreadSafe => false;
2123

2224
public IReadOnlyList<string> Messages
@@ -63,6 +65,17 @@ public ImmutableList<JsonRpc.TraceEvents> Ids
6365
}
6466
}
6567

68+
public ImmutableList<(JsonRpc.TraceEvents TraceEventId, Guid ActivityId)> EventsWithActivityIds
69+
{
70+
get
71+
{
72+
lock (this.eventsWithActivityIds)
73+
{
74+
return this.eventsWithActivityIds.ToImmutable();
75+
}
76+
}
77+
}
78+
6679
public AsyncAutoResetEvent MessageReceived { get; } = new AsyncAutoResetEvent();
6780

6881
public override void TraceTransfer(TraceEventCache? eventCache, string source, int id, string? message, Guid relatedActivityId)
@@ -87,6 +100,11 @@ public override void TraceEvent(TraceEventCache? eventCache, string source, Trac
87100
this.events.Add((eventType, format is null ? null : string.Format(CultureInfo.InvariantCulture, format, args ?? Array.Empty<object?>())));
88101
}
89102

103+
lock (this.eventsWithActivityIds)
104+
{
105+
this.eventsWithActivityIds.Add(((JsonRpc.TraceEvents)id, Trace.CorrelationManager.ActivityId));
106+
}
107+
90108
base.TraceEvent(eventCache, source, eventType, id, format, args);
91109
}
92110

@@ -102,6 +120,11 @@ public override void TraceEvent(TraceEventCache? eventCache, string source, Trac
102120
this.events.Add((eventType, message));
103121
}
104122

123+
lock (this.eventsWithActivityIds)
124+
{
125+
this.eventsWithActivityIds.Add(((JsonRpc.TraceEvents)id, Trace.CorrelationManager.ActivityId));
126+
}
127+
105128
base.TraceEvent(eventCache, source, eventType, id, message);
106129
}
107130

@@ -117,6 +140,11 @@ public override void TraceEvent(TraceEventCache? eventCache, string source, Trac
117140
this.events.Add((eventType, null));
118141
}
119142

143+
lock (this.eventsWithActivityIds)
144+
{
145+
this.eventsWithActivityIds.Add(((JsonRpc.TraceEvents)id, Trace.CorrelationManager.ActivityId));
146+
}
147+
120148
base.TraceEvent(eventCache, source, eventType, id);
121149
}
122150

test/StreamJsonRpc.Tests/JsonRpcTests.cs

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2801,6 +2801,52 @@ public async Task CorrelationManagerActivitiesPropagate(string? traceState)
28012801
}
28022802
}
28032803

2804+
[Fact]
2805+
public async Task CorrelationManagerActivity_ServerDispatchTracesHaveActivityId()
2806+
{
2807+
// Verify that all server-side StreamJsonRpc traces emitted during RPC dispatch
2808+
// (RequestReceived, LocalInvocation) have a non-empty activity ID that matches
2809+
// the activity ID seen by the server method during execution.
2810+
var strategy = new CorrelationManagerTracingStrategy
2811+
{
2812+
TraceSource = new TraceSource("strategy", SourceLevels.ActivityTracing | SourceLevels.Information),
2813+
};
2814+
this.clientRpc.AllowModificationWhileListening = true;
2815+
this.clientRpc.ActivityTracingStrategy = strategy;
2816+
this.serverRpc.AllowModificationWhileListening = true;
2817+
this.serverRpc.ActivityTracingStrategy = strategy;
2818+
2819+
Guid clientActivityId = Guid.NewGuid();
2820+
Trace.CorrelationManager.ActivityId = clientActivityId;
2821+
Guid serverActivityId;
2822+
try
2823+
{
2824+
serverActivityId = await this.clientRpc.InvokeWithCancellationAsync<Guid>(nameof(Server.GetCorrelationManagerActivityId), cancellationToken: this.TimeoutToken);
2825+
}
2826+
finally
2827+
{
2828+
Trace.CorrelationManager.ActivityId = Guid.Empty;
2829+
}
2830+
2831+
// The server should have seen a non-empty, distinct activity ID.
2832+
Assert.NotEqual(Guid.Empty, serverActivityId);
2833+
Assert.NotEqual(clientActivityId, serverActivityId);
2834+
2835+
// Every dispatch-related trace on the server should have the same activity ID
2836+
// that the server method observed during execution.
2837+
var serverDispatchTraces = this.serverTraces.EventsWithActivityIds
2838+
.Where(e => e.TraceEventId == JsonRpc.TraceEvents.RequestReceived
2839+
|| e.TraceEventId == JsonRpc.TraceEvents.LocalInvocation)
2840+
.ToList();
2841+
2842+
Assert.NotEmpty(serverDispatchTraces);
2843+
2844+
foreach (var (traceEventId, activityId) in serverDispatchTraces)
2845+
{
2846+
Assert.Equal(serverActivityId, activityId);
2847+
}
2848+
}
2849+
28042850
[Theory]
28052851
[InlineData(null)]
28062852
[InlineData("")]

0 commit comments

Comments
 (0)