How to unit test Activity, or how to bypass the concurrency issue with ActivityListener?

Recently I've started writing some integration tests, and earlier today I started trying to add tests for my telemetry. Using the System.Diagnostics.ActivitySource.AddActivityListener method this seemingly worked quite well - while running a single test at a time. After finalizing the tests I pressed the "run all tests" button in my IDE to validate that I hadn't broken anything, and everything blew up. This took me several hours to debug, but in the end I figured out it was a heavy concurrency issue at play with regards to the ActivityListener.

Currently, the only way to test activities [... that I've figured out] is using the ActivityListener, and for the life of me I haven't been able to figure out how to a) Work around the concurrency issue, or b) Make xUnit not run in parallel (which is far from ideal even if I did figure out how).

Here are a few concrete examples of what I want to test:

// Arrange
ValidationProblemDetails expectedValidationProblemDetails = ...;
MultipartFormDataContent formContent = ...;
using var client = _factory.CreateClient();
Uri requestUri = ...;

// Act
var response = await client.PostAsync(requestUri, formContent).ConfigureAwait(true);
var responseContent = await response.Content.ReadFromJsonAsync<ValidationProblemDetails>().ConfigureAwait(true);

// Assert
response.StatusCode.Should().Be(HttpStatusCode.UnprocessableEntity);
responseContent.Should().BeEquivalentTo(expectedValidationProblemDetails);

_activities
	.Should()
	.ContainSingle(x =>
		string.Equals(x.OperationName, "Microsoft.AspNetCore.Hosting.HttpRequestIn", StringComparison.Ordinal)
	)
	.Which.TagObjects.Should()
	.ContainSingle(x => string.Equals(x.Key, "http.response.status_code", StringComparison.Ordinal))
	.Which.Value.Should()
	.Be(expected: 422);

where _activities collection is populated like this (this is where the problem lies).

_activities = [];
ActivityListener listener =
	new()
	{
		Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData,
		ActivityStarted = activity => _activities.Add(activity),
		ShouldListenTo = _ => true,
		SampleUsingParentId = (ref ActivityCreationOptions<string> _) => ActivitySamplingResult.AllData,
	};
ActivitySource.AddActivityListener(listener);

So my question is this:

Is this how you're supposed to test activities? If it is, then it's clearly not working. It does feel using the listener like this, having a closure and updating it in a callback like this.
If it's not, what is it? I couldn't find documentation anywhere on this. The closest I got was this article, in which case all I saw was the following, which implies it's possible

In my typical use case, I'm using sampling to do integration testing, so I'll typically have my listener set to ActivitySamplingResult.AllData.

Have a similar question before dotnet/extensions#4825
Maybe we could start an activity before the tracing logic then we could filter the activities using parentId/traceId

@WeihanLi

@WeihanLi I saw your thread (probably should've mentioned it), but I didn't get it to work. Parent was always null. Did you figure out how to do it?

It's still very much a hack, but still - if it works, it works 😅

@KennethHoff

@KennethHoff I add an example here, hope it helps
https://github.com/WeihanLi/SamplesInPractice/blob/main/XunitSample/ActivityTest.cs

public class ActivityTest
{
    [Fact]
    public void ActivityListenTest()
    {
        var activities = new List<Activity>();
        
        using var listener = new ActivityListener();
        listener.ShouldListenTo = s => s.Name == nameof(ActivityTest);
        listener.Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllData;
        listener.ActivityStopped += a => activities.Add(a);
        ActivitySource.AddActivityListener(listener);

        using var activity = ActivitySource.StartActivity();
        var activityId = activity?.Id ?? string.Empty;
        var traceId = activity?.TraceId.ToHexString();
        
        ActivityDemo();
        
        Assert.NotEmpty(activities);
        var capturedActivity = activities.FirstOrDefault(x => x.TraceId.ToHexString() == traceId);
        Assert.NotNull(capturedActivity);
        Assert.Equal(activityId, capturedActivity.ParentId);
        Assert.Equal(traceId, capturedActivity.TraceId.ToHexString());
        Assert.Equal("1", capturedActivity.GetTagItem("test.id")?.ToString());
    }
    
    private static readonly ActivitySource ActivitySource = new(nameof(ActivityTest));
    private static void ActivityDemo()
    {
        using var activity = ActivitySource.StartActivity();
        Thread.Sleep(100);
        activity?.SetTag("test.id", "1");
    }
}

@WeihanLi

@WeihanLi For whatever reason, the traceId does not cross this boundary. I'm guessing this is an Asp.Net Core thing though.

(No, moving the activity creation to after factory or client creation has no effect)

for asp.net core, there's little difference, let me try with another example
https://github.com/WeihanLi/XunitDependencyInjection.Samples/blob/main/P6_MinimalAPI/MinimalApiTest/ApiTest.cs#L33

[Fact]
public async Task ActivityTest()
{
    var activities = new List<Activity>();
    using var activitySource = new ActivitySource(nameof(ActivityTest));
    
    using var listener = new ActivityListener();
    listener.ShouldListenTo = s => true;
    listener.Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData;
    listener.ActivityStopped = a => activities.Add(a);
    ActivitySource.AddActivityListener(listener);

    using var activity = activitySource.StartActivity();
    var activityId = activity?.Id ?? string.Empty;
    var traceId = activity?.TraceId.ToHexString();
    using var requestMessage = new HttpRequestMessage(HttpMethod.Get, "/activityId");
    requestMessage.Headers.TryAddWithoutValidation("traceparent", activityId);
    using var responseMessage = await _testClient.SendAsync(requestMessage);
    Assert.True(responseMessage.IsSuccessStatusCode);
    var responseText = await responseMessage.Content.ReadAsStringAsync();
    var responseActivityParse = ActivityContext.TryParse(responseText, null, out var activityContext);
    Assert.True(responseActivityParse);                                                                                                                                                                                                                                                                                                                                                                                                                                                                          
    Assert.Equal(traceId, activityContext.TraceId.ToHexString());
    Assert.True(activities.Count > 1);
    Assert.True(activities.Exists(a=> a.ParentId == activityId));
}

you can attach the parentId as traceparent request header, see details: https://github.com/dotnet/aspnetcore/blob/db01a95c38c1966664f311d5507c600f210f475d/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs#L379

@WeihanLi

@WeihanLi !! That seems to have worked! Hurray!

It's still very ugly, but at least you (seem to be able to) work around it somewhat!

@tarekgh

Yeah, it is 😅. Hope to see some more elegant ways from others.
@tarekgh any suggestions about this?

@WeihanLi

@WeihanLi
Actually, never mind - It doesn't seem like it actually fixed it. It made it better, but by no means "fixed".

Concurrency issues like this are an absolute hell to debug, as they work while debugging/running one at a time...

@KennethHoff

@KennethHoff in your test mentioned in #98854 (comment) what exactly the failure you were getting?

Your listener's callbacks can be called synchronousely if more than one activity get started in same time from different threads. I am seeing your listener callback is not written in thread safe way. I mean:

ActivityStarted = activity => _activities.Add(activity),

Should be done like

ActivityStarted = activity => lock (_activities)  { _activities.Add(activity); },

If you can tell exactly the failure you are seeing or send a complete isolated repro I can try to help you more. Thanks!

CC @noahfalk

@tarekgh

@tarekgh https://github.com/KennethHoff/Repros/tree/b25106f575ee5c782f99dfcfe89b5fc6eb53a900/ActivityTesting

I've figured a few things out:

1.Azure.Monitor.OpenTelemetry.AspNetCore is implemented even worse than I originally thought. I've always known it does things in their own wonky non-composable way, but I didn't think they did it in such a bad way that it causes concurrency issues.
2. OpenTelemetry.Instrumentation.AspNetCore is inconsistent. Sometimes the DisplayName for the request's activity is "POST <endpointName>" other times it's just "POST" This is much less of an issue than the Azure.Monitor.OpenTelemetry.AspNetCore one though, but still good to know.

@reyang

I think the issue is not related to activity listener or concurrency inside the runtime.

@reyang @CodeBlanch @cijothomas Do you have any insights into what might be happening in this situation?

The test:
https://github.com/KennethHoff/Repros/blob/b25106f575ee5c782f99dfcfe89b5fc6eb53a900/ActivityTesting/ActivityTesting.Tests/IntegrationTests.cs#L62

is calling var response = await client.PostAsync(uri, httpContent); and then attempt to retrieve the count of activities generated from this call, using the same trace ID as the parent activity created by the test. The number of activities sharing the same trace ID also increases. This issue not happening when not using Azure monitor configuration. Here is small example of the activities get created during one iteration of the test.

trace Id ... id ... OperationName ... DisplayName
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-e8bd0548d43ff04d-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... Microsoft.AspNetCore.Hosting.HttpRequestIn
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-34552cf2caf10bda-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-4126114da479e5cf-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-fb395df803350b99-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-bb41963b10aea6ab-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-e04ec343a462249c-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-6c3da9bd1570cd46-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-b6034f0dc8c601ba-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-40d0fe00a21254a8-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-27ab0174d4804fa7-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-3579db0b517613ea-01 ... Microsoft.AspNetCore.Hosting.HttpRequestIn ... POST my-api-endpoint
efd1fe06966a9a076124cf359c2a36b5 ... 00-efd1fe06966a9a076124cf359c2a36b5-2aa92f1a87c891cf-01 ... my-api-endpoint-activity ... my-api-endpoint-activity

@KennethHoff

@KennethHoff as it looks the issue now is not about the activity listening, I am closing this issue here and suggest you log it in https://github.com/microsoft/AzureMonitorCommunity to get better traction. Thanks for your report.

@KennethHoff

@KennethHoff - Are your tests using WebApplicationFactory and divided across multiple test classes? I'm guessing they are based on what you described although nothing in the example code explicitly shows it.

Each WebApplicationFactory has a service container in it and one of the items in that container is the ActivitySource that the corresponding Kestrel host is using to emit all of its telemetry. You could retrieve that ActivitySource instance like this:

var activitySource = _factory.Services.GetRequiredService<ActivitySource>();

Then down in your ActivityListener instead of telling it to listen to all sources (which includes the sources being used by the concurrently running tests), just tell it to listen to the source being used in this test:

ShouldListenTo = source => source == activitySource

This way you can listen to only the telemetry from your test and not the telemetry from other concurrently running tests. It's possible there are still some other issues lurking but I suspect this was probably a big one causing you concurrency trouble.

Hope that helps!

@noahfalk

@noahfalk This seems to have fixed the concurrency issue, but it creates another issue; It only works for the built-in ActivitySource, so it doesn't allow me to test my own custom activities.

I tried adding my own (keyed) singleton ActivitySource and use that for my own activities. That worked, but that created it's own concurrency issues (... somehow... See the previously linked repro repo (Here) - now updated with DI-based version.

I then tried to just use the Kestrel-provided one*. That worked, but that feels wrong, but is there a reason not to do that?

It also seemed to have cleaned up the mess caused by UseAzureMonitor. All combinations of UseAzureMonitor and UseAspNetCoreInstrumentation now works identically (Except for the one with both set to false which is lacking OTel-stuff, which makes sense), but that in itself is a little worrying - What telemetry did I just lose that AzureMonitor previously added? 🤔

* Technically I did it the other way around, as you can see in the GitHub commit history ;)

Navigation Menu

Repository navigation

How to unit test `Activity`, or how to bypass the concurrency issue with `ActivityListener`? #98854

14 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

How to unit test Activity, or how to bypass the concurrency issue with ActivityListener? #98854

Description

Activity

WeihanLi commented on Feb 24, 2024

KennethHoff commented on Feb 24, 2024

WeihanLi commented on Feb 25, 2024

KennethHoff commented on Feb 25, 2024

WeihanLi commented on Feb 25, 2024

KennethHoff commented on Feb 25, 2024

WeihanLi commented on Feb 25, 2024

KennethHoff commented on Feb 25, 2024

tarekgh commented on Feb 25, 2024

14 remaining items

KennethHoff commented on Feb 26, 2024

tarekgh commented on Feb 27, 2024

tarekgh commented on Feb 27, 2024

noahfalk commented on Feb 27, 2024

KennethHoff commented on Feb 27, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

How to unit test `Activity`, or how to bypass the concurrency issue with `ActivityListener`? #98854