diff --git a/src/OpenTelemetry/Internal/OpenTelemetrySdkEventSource.cs b/src/OpenTelemetry/Internal/OpenTelemetrySdkEventSource.cs index 38765609b54..1243a36e085 100644 --- a/src/OpenTelemetry/Internal/OpenTelemetrySdkEventSource.cs +++ b/src/OpenTelemetry/Internal/OpenTelemetrySdkEventSource.cs @@ -69,7 +69,7 @@ public void ActivityStarted(Activity activity) // https://github.com/dotnet/runtime/issues/61857 var activityId = string.Concat("00-", activity.TraceId.ToHexString(), "-", activity.SpanId.ToHexString()); activityId = string.Concat(activityId, activity.ActivityTraceFlags.HasFlag(ActivityTraceFlags.Recorded) ? "-01" : "-00"); - this.ActivityStarted(activity.DisplayName, activityId); + this.ActivityStart(activity.DisplayName, activityId); } } @@ -78,7 +78,7 @@ public void ActivityStopped(Activity activity) { if (this.IsEnabled(EventLevel.Verbose, EventKeywords.All)) { - this.ActivityStopped(activity.DisplayName, activity.Id); + this.ActivityStop(activity.DisplayName, activity.Id); } } @@ -175,14 +175,14 @@ public void ObservableInstrumentCallbackException(string exception) this.WriteEvent(16, exception); } - [Event(24, Message = "Activity started. Name = '{0}', Id = '{1}'.", Level = EventLevel.Verbose)] - public void ActivityStarted(string name, string id) + [Event(24, Message = "Activity started. Name = '{0}', Id = '{1}'.", Level = EventLevel.Verbose, Opcode = EventOpcode.Start)] + public void ActivityStart(string name, string id) { this.WriteEvent(24, name, id); } - [Event(25, Message = "Activity stopped. Name = '{0}', Id = '{1}'.", Level = EventLevel.Verbose)] - public void ActivityStopped(string name, string? id) + [Event(25, Message = "Activity stopped. Name = '{0}', Id = '{1}'.", Level = EventLevel.Verbose, Opcode = EventOpcode.Stop)] + public void ActivityStop(string name, string? id) { this.WriteEvent(25, name, id); } diff --git a/test/Benchmarks/EventSourceBenchmarks.cs b/test/Benchmarks/EventSourceBenchmarks.cs index f8304368632..8bffa148d0d 100644 --- a/test/Benchmarks/EventSourceBenchmarks.cs +++ b/test/Benchmarks/EventSourceBenchmarks.cs @@ -17,7 +17,7 @@ public void EventWithIdAllocation() activity.Start(); activity.Stop(); - OpenTelemetrySdkEventSource.Log.ActivityStarted(activity.OperationName, activity.Id); + OpenTelemetrySdkEventSource.Log.ActivityStart(activity.OperationName, activity.Id); } [Benchmark] diff --git a/test/OpenTelemetry.Tests/EventSourceTest.cs b/test/OpenTelemetry.Tests/EventSourceTest.cs index 5e7d3e2f258..32f27b62ad8 100644 --- a/test/OpenTelemetry.Tests/EventSourceTest.cs +++ b/test/OpenTelemetry.Tests/EventSourceTest.cs @@ -6,6 +6,7 @@ namespace OpenTelemetry.Tests; +[Collection("Uses-OpenTelemetrySdkEventSource")] // Prevent parallel execution with other tests that exercise the SdkEventSource public class EventSourceTest { [Fact] diff --git a/test/OpenTelemetry.Tests/Internal/SdkEventSourceTest.cs b/test/OpenTelemetry.Tests/Internal/SdkEventSourceTest.cs new file mode 100644 index 00000000000..11f643d8259 --- /dev/null +++ b/test/OpenTelemetry.Tests/Internal/SdkEventSourceTest.cs @@ -0,0 +1,121 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 +#nullable enable + +using System.Diagnostics; +using System.Diagnostics.Tracing; +using OpenTelemetry.Internal; +using OpenTelemetry.Trace; +using Xunit; + +namespace OpenTelemetry.Tests.Internal; + +[Collection("Uses-OpenTelemetrySdkEventSource")] // Prevent parallel execution with other tests that exercise the SdkEventSource +public class SdkEventSourceTest : IDisposable +{ + private readonly SdkEventListener listener = new(); + + public void Dispose() + { + this.listener.Dispose(); + } + + [Fact] + public void ActivityStartUsesOpCodeStart() + { + using (TracerProvider tracerProvider = Sdk.CreateTracerProviderBuilder() + .AddSource("TestSource") + .Build()) + { + // Clear any events that were emitted during Build. + this.listener.Events.Clear(); + + const int numActivities = 4; + + using ActivitySource activitySource = new("TestSource"); + for (int i = 0; i < numActivities; i++) + { + using Activity? activity = activitySource.StartActivity($"Test Activity {i}"); + } + + // There should be 2 events for each activity: ActivityStart and ActivityStop. + Assert.Equal(numActivities * 2, this.listener.Events.Count); + + HashSet activityIds = []; + for (int i = 0; i < numActivities; i++) + { + EventWrittenEventArgs startEvent = this.listener.Events[i * 2]; + EventWrittenEventArgs stopEvent = this.listener.Events[(i * 2) + 1]; + + Assert.Equal(nameof(OpenTelemetrySdkEventSource.ActivityStart), startEvent.EventName); + Assert.Equal(nameof(OpenTelemetrySdkEventSource.ActivityStop), stopEvent.EventName); + + // Start and Stop should be matched on ActivityId. + Assert.Equal(startEvent.ActivityId, stopEvent.ActivityId); + + // ActivityIds should be unique. + Assert.True(activityIds.Add(startEvent.ActivityId)); + } + } + } + + private sealed class SdkEventListener : EventListener + { + private static readonly string SdkEventSourceName = EventSource.GetName(typeof(OpenTelemetrySdkEventSource)); + private readonly HashSet eventSourcesEnabled = []; + + public List Events { get; } = []; + + public override void Dispose() + { + try + { + foreach (EventSource eventSource in this.eventSourcesEnabled) + { + this.DisableEvents(eventSource); + } + } + finally + { + base.Dispose(); + } + } + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == SdkEventSourceName) + { + this.eventSourcesEnabled.Add(eventSource); + this.EnableEvents(eventSource, EventLevel.Verbose, EventKeywords.All); + } + else if (eventSource.Name == "System.Threading.Tasks.TplEventSource") + { + // In addition to the OpenTelemetrySdkEventSource we need + // the TPL EventSource to enable activity tracking. When + // enabled and an EventSource writes events with + // EventOpCode.Start/Stop, then the ActivityTracker will + // generate new path-like ActivityIDs. + // Also note that activity tracking requires that the + // Start/Stop events are a matched pair, named like + // "xyzStart" and "xyzStop". ActivityTracker matches the + // stop event with the start event by recognizing those + // exact suffixes. + this.eventSourcesEnabled.Add(eventSource); + const EventKeywords taskFlowActivityIds = (EventKeywords)0x80; + this.EnableEvents(eventSource, EventLevel.Informational, taskFlowActivityIds); + } + + base.OnEventSourceCreated(eventSource); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (eventData.EventSource.Name == SdkEventSourceName) + { + this.Events.Add(eventData); + } + + base.OnEventWritten(eventData); + } + } +} diff --git a/test/OpenTelemetry.Tests/Internal/SelfDiagnosticsEventListenerTest.cs b/test/OpenTelemetry.Tests/Internal/SelfDiagnosticsEventListenerTest.cs index 58777971b5d..147ed141cc7 100644 --- a/test/OpenTelemetry.Tests/Internal/SelfDiagnosticsEventListenerTest.cs +++ b/test/OpenTelemetry.Tests/Internal/SelfDiagnosticsEventListenerTest.cs @@ -9,6 +9,7 @@ namespace OpenTelemetry.Internal.Tests; +[Collection("Uses-OpenTelemetrySdkEventSource")] // Prevent parallel execution with other tests that exercise the SdkEventSource public class SelfDiagnosticsEventListenerTest { private const string LOGFILEPATH = "Diagnostics.log"; @@ -32,7 +33,7 @@ public void SelfDiagnosticsEventListener_EventSourceSetup_LowerSeverity() _ = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresher); // Emitting a Verbose event. Or any EventSource event with lower severity than Error. - OpenTelemetrySdkEventSource.Log.ActivityStarted("Activity started", "1"); + OpenTelemetrySdkEventSource.Log.ActivityStart("Activity started", "1"); Assert.False(configRefresher.TryGetLogStreamCalled); } @@ -115,7 +116,7 @@ public void SelfDiagnosticsEventListener_EmitEvent_OmitAsConfigured() _ = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresher); // Act: emit an event with severity lower than configured - OpenTelemetrySdkEventSource.Log.ActivityStarted("ActivityStart", "123"); + OpenTelemetrySdkEventSource.Log.ActivityStart("ActivityStart", "123"); // Assert Assert.False(configRefresher.TryGetLogStreamCalled);