Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Multiple instances of OpenTelemetry-Sdk EventSource #4516

Closed
MrLuje opened this issue May 25, 2023 · 7 comments · Fixed by #4586
Closed

Multiple instances of OpenTelemetry-Sdk EventSource #4516

MrLuje opened this issue May 25, 2023 · 7 comments · Fixed by #4586
Labels
bug Something isn't working
Milestone

Comments

@MrLuje
Copy link

MrLuje commented May 25, 2023

Bug Report

List of all OpenTelemetry NuGet
packages
and version that you are
using (e.g. OpenTelemetry 1.0.2):

  <package id="OpenTelemetry" version="1.4.0" targetFramework="net48" />
  <package id="OpenTelemetry.Api" version="1.4.0" targetFramework="net48" />
  <package id="OpenTelemetry.Api.ProviderBuilderExtensions" version="1.4.0" targetFramework="net48" />
  <package id="OpenTelemetry.Exporter.Console" version="1.4.0" targetFramework="net48" />
  <package id="OpenTelemetry.Exporter.OpenTelemetryProtocol" version="1.4.0" targetFramework="net48" />

Runtime version (e.g. net462, net48, netcoreapp3.1, net6.0 etc. You can
find this information from the *.csproj file):

  • net48

Symptom

I have a console app that generate metrics & traces for testing purpose with a console & otlp exporter.
I'm receiving the metrics but no traces.
I have another test app in dotnet core on the same endpoint that works fine.

What is the expected behavior?

I want both metric & traces

What is the actual behavior?

I only get the metrics in my OTEL system

Reproduce

You can use this repo : https://github.com/MrLuje/opentelemetry-netfx-issue but fullcode below :

var activitySource = new ActivitySource("MyCompany.MyProduct.MyLibrary");
            var trace = Sdk.CreateTracerProviderBuilder()
                .AddSource("MyCompany.MyProduct.MyLibrary")
                .AddConsoleExporter()
                .AddOtlpExporter(b => b.Protocol = OpenTelemetry.Exporter.OtlpExportProtocol.HttpProtobuf)
                .Build();

            var meter = new Meter("TestMeter");
            var metric = Sdk.CreateMeterProviderBuilder()
                .AddConsoleExporter()
                .AddOtlpExporter(b => b.Protocol = OpenTelemetry.Exporter.OtlpExportProtocol.HttpProtobuf)
                .AddMeter(meter.Name)
                .Build();

            var counter = meter.CreateCounter<int>("testcounter", "thing", "A count of things");

            Console.WriteLine(@"This app will endlessly publish :
Trace with Service Name = unknown_service");

            while(true)
            {
                var activity = activitySource.StartActivity("SayHello")
                    .SetTag("foo", 1)
                    .SetTag("bar", "Hello, World!")
                    .SetTag("baz", new int[] { 1, 2, 3 })
                    .SetStatus(ActivityStatusCode.Ok);
                counter.Add(1);

                await Task.Delay(TimeSpan.FromSeconds(5));
                Console.WriteLine("------------------------------------------------------------------");
            }

Additional Context

In debug, I got an exception when calling Sdk.CreateTracerProviderBuilder

System.ArgumentException: 'Il existe déjà une instance d'EventSource utilisant le GUID af2d5796-946b-50cb-5f76-166a609afcbb.'

Diagnostic (OTEL_DIAGNOSTICS) run below :

If you are seeing this message, it means that the OpenTelemetry SDK has successfully created the log file used to write self-diagnostic logs. This file will be appended with logs as they appear. If you do not see any logs following this line, it means no logs of the configured LogLevel is occurring. You may change the LogLevel to show lower log levels, so that logs of lower severities will be shown.
2023-05-25T10:48:34.8142103Z:TracerProviderSdk event: '{0}'{Building TracerProvider.}
2023-05-25T10:48:34.8452095Z:{ERROR: Exception in Command Processing for EventSource OpenTelemetry-Sdk: Il existe déjà une instance d'EventSource utilisant le GUID af2d5796-946b-50cb-5f76-166a609afcbb.}
2023-05-25T10:48:34.9011790Z:TracerProviderSdk event: '{0}'{Processors added = "OpenTelemetry.SimpleActivityExportProcessor;OpenTelemetry.BatchActivityExportProcessor".}
2023-05-25T10:48:34.9021796Z:TracerProviderSdk event: '{0}'{TracerProvider built successfully.}
2023-05-25T10:48:34.9102091Z:MeterProviderSdk event: '{0}'{Building MeterProvider.}
2023-05-25T10:48:34.9191756Z:MeterProviderSdk event: '{0}'{Exporters added = "OpenTelemetry.Exporter.ConsoleMetricExporter (Paired with PeriodicExportingMetricReader exporting at 10000 milliseconds intervals.);OpenTelemetry.Exporter.OtlpMetricExporter (Paired with PeriodicExportingMetricReader exporting at 60000 milliseconds intervals.)".}
2023-05-25T10:48:34.9191756Z:MeterProviderSdk event: '{0}'{Listening to following meters = "TestMeter".}
2023-05-25T10:48:34.9201746Z:MeterProviderSdk event: '{0}'{Number of views configured = 0.}
2023-05-25T10:48:34.9231758Z:MeterProviderSdk event: '{0}'{MeterProvider built successfully.}
2023-05-25T10:48:34.9241747Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "testcounter" of Meter = "TestMeter".}
2023-05-25T10:48:34.9371755Z:MeterProviderSdk event: '{0}'{Completed publishing Instrument = "testcounter" of Meter = "TestMeter".}
2023-05-25T10:48:34.9501766Z:Activity started. OperationName = '{0}', Id = '{1}'.{SayHello}{00-343e77b6d5d3fde2cd01734a244891df-afe6984f42ae4920-01}
2023-05-25T10:48:39.9682809Z:Activity started. OperationName = '{0}', Id = '{1}'.{SayHello}{00-343e77b6d5d3fde2cd01734a244891df-1efef2c57352cf16-01}
2023-05-25T10:48:44.9306344Z:MetricReader event: '{0}'{PeriodicExportingMetricReader calling MetricReader.Collect because the export interval has elapsed.}
2023-05-25T10:48:44.9327094Z:MetricReader event: '{0}'{MetricReader.Collect method called.}
2023-05-25T10:48:44.9366873Z:MetricReader event: '{0}'{MetricReader.OnCollect called.}
2023-05-25T10:48:44.9366873Z:MetricReader event: '{0}'{Observable instruments collected.}
2023-05-25T10:48:44.9376899Z:MetricReader event: '{0}'{ProcessMetrics called.}
2023-05-25T10:48:44.9386874Z:MetricReader event: '{0}'{BaseExportingMetricReader calling OpenTelemetry.Exporter.ConsoleMetricExporter.Export method.}
2023-05-25T10:48:44.9452561Z:{ERROR: Exception in Command Processing for EventSource OpenTelemetry-Sdk: Il existe déjà une instance d'EventSource utilisant le GUID af2d5796-946b-50cb-5f76-166a609afcbb.}
2023-05-25T10:48:44.9482235Z:MetricReader event: '{0}'{OpenTelemetry.Exporter.ConsoleMetricExporter.Export succeeded.}
2023-05-25T10:48:44.9482235Z:MetricReader event: '{0}'{ProcessMetrics succeeded.}
2023-05-25T10:48:44.9482235Z:MetricReader event: '{0}'{MetricReader.Collect succeeded.}
2023-05-25T10:48:44.9774960Z:Activity started. OperationName = '{0}', Id = '{1}'.{SayHello}{00-343e77b6d5d3fde2cd01734a244891df-dbdbcc30fe91857d-01}
2023-05-25T10:48:49.9926687Z:Activity started. OperationName = '{0}', Id = '{1}'.{SayHello}{00-343e77b6d5d3fde2cd01734a244891df-57a516c23dbe627f-01}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{PeriodicExportingMetricReader calling MetricReader.Collect because the export interval has elapsed.}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{MetricReader.Collect method called.}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{MetricReader.OnCollect called.}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{Observable instruments collected.}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{ProcessMetrics called.}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{BaseExportingMetricReader calling OpenTelemetry.Exporter.ConsoleMetricExporter.Export method.}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{OpenTelemetry.Exporter.ConsoleMetricExporter.Export succeeded.}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{ProcessMetrics succeeded.}
2023-05-25T10:48:54.9228839Z:MetricReader event: '{0}'{MetricReader.Collect succeeded.}

@MrLuje MrLuje added the bug Something isn't working label May 25, 2023
@Kielek
Copy link
Contributor

Kielek commented May 25, 2023

You have never disposed/stopped acivity.

Please try following code

            while(true)
            {
                using (var activity = activitySource.StartActivity("SayHello"))
                {
                    activity?.SetTag("foo", 1)
                        .SetTag("bar", "Hello, World!")
                        .SetTag("baz", new int[] {1, 2, 3})
                        .SetStatus(ActivityStatusCode.Ok);
                    counter.Add(1);

                    await Task.Delay(TimeSpan.FromSeconds(5));
                }

                Console.WriteLine("------------------------------------------------------------------");
            }

@MrLuje
Copy link
Author

MrLuje commented May 25, 2023

Oups, good catch... converted from vb.net and missed it
So the EventSource guid already registered exception is nothing to be worried about ?

@Kielek
Copy link
Contributor

Kielek commented May 25, 2023

I was not able to reproduce this issue, but definitely it should not occur. Do you have full stacktrace?

@MrLuje
Copy link
Author

MrLuje commented May 25, 2023

System.ArgumentException: 'Il existe déjà une instance d'EventSource utilisant le GUID af2d5796-946b-50cb-5f76-166a609afcbb.'

 	mscorlib.dll!System.Diagnostics.Tracing.EventSource.EnsureDescriptorsInitialized()	Unknown	No symbols loaded.
 	mscorlib.dll!System.Diagnostics.Tracing.EventSource.DoCommand(System.Diagnostics.Tracing.EventCommandEventArgs commandArgs)	Unknown	No symbols loaded.
 	mscorlib.dll!System.Diagnostics.Tracing.EventSource.Initialize(System.Guid eventSourceGuid, string eventSourceName, string[] traits)	Unknown	No symbols loaded.
 	mscorlib.dll!System.Diagnostics.Tracing.EventSource.EventSource(System.Diagnostics.Tracing.EventSourceSettings settings, string[] traits)	Unknown	No symbols loaded.
 	OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Internal.OpenTelemetrySdkEventSource.OpenTelemetrySdkEventSource()	Unknown	Symbols loaded.
	OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Internal.OpenTelemetrySdkEventSource.OpenTelemetrySdkEventSource() Line 29	C#	Symbols loaded.
 	[Native to Managed Transition]		Annotated Frame
 	[Managed to Native Transition]		Annotated Frame
 	OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Exporter.OtlpExporterOptions.OtlpExporterOptions(Microsoft.Extensions.Configuration.IConfiguration configuration, OpenTelemetry.Trace.BatchExportActivityProcessorOptions defaultBatchOptions) Line 153	C#	Symbols loaded.
 	OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Exporter.OtlpExporterOptions.RegisterOtlpExporterOptionsFactory.AnonymousMethod__44_0(System.IServiceProvider sp, Microsoft.Extensions.Configuration.IConfiguration configuration, string name) Line 201	C#	Symbols loaded.
 	OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Internal.ConfigurationExtensions.RegisterOptionsFactory.AnonymousMethod__1(Microsoft.Extensions.Configuration.IConfiguration c, string n) Line 152	C#	Symbols loaded.
 	OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!Microsoft.Extensions.Options.DelegatingOptionsFactory<OpenTelemetry.Exporter.OtlpExporterOptions>.Create(string name) Line 77	C#	Symbols loaded.
 	OpenTelemetry.Exporter.OpenTelemetryProtocol.dll!OpenTelemetry.Trace.OtlpTraceExporterHelperExtensions.AddOtlpExporter.AnonymousMethod__1(System.IServiceProvider sp) Line 81	C#	Symbols loaded.
 	OpenTelemetry.dll!OpenTelemetry.Trace.TracerProviderBuilderExtensions.AddProcessor.AnonymousMethod__0(System.IServiceProvider sp, OpenTelemetry.Trace.TracerProviderBuilder builder) Line 231	C#	Symbols loaded.
 	OpenTelemetry.Api.ProviderBuilderExtensions.dll!OpenTelemetry.Trace.OpenTelemetryDependencyInjectionTracingServiceCollectionExtensions.ConfigureTracerProviderBuilderCallbackWrapper.ConfigureBuilder(System.IServiceProvider serviceProvider, OpenTelemetry.Trace.TracerProviderBuilder tracerProviderBuilder)	Unknown	No symbols loaded.
 	OpenTelemetry.dll!OpenTelemetry.Trace.TracerProviderSdk.TracerProviderSdk(System.IServiceProvider serviceProvider, bool ownsServiceProvider) Line 62	C#	Symbols loaded.
 	OpenTelemetry.dll!OpenTelemetry.Trace.TracerProviderBuilderBase.Build() Line 176	C#	Symbols loaded.
 	OpenTelemetry.dll!OpenTelemetry.Trace.TracerProviderBuilderExtensions.Build(OpenTelemetry.Trace.TracerProviderBuilder tracerProviderBuilder) Line 250	C#	Symbols loaded.
 	ConsoleApp1.exe!ConsoleApp1.Program.Main(string[] args) Line 16	C#	Symbols loaded.
 	ConsoleApp1.exe!ConsoleApp1.Program.<Main>(string[] args)	Unknown	Symbols loaded.

@Kielek
Copy link
Contributor

Kielek commented May 29, 2023

I think that now I understand where there issue occurs.

OpenTelemetrySdkEventSource class is compiled directly into few projects

  • OpenTelemetry
  • OpenTelemetry.Exporter.Console
  • OpenTelemetry.Exporter.Jaeger
  • OpenTelemetry.Exporter.OpenTelemetryProtocol
  • OpenTelemetry.Exporter.Zipkin.

In each of this projects instance of this class can be instantiated separately. It will leads to An instance of EventSource with Guid af2d5796-946b-50cb-5f76-166a609afcbb already exists. exception.

The guid is generated from EventSourceAttribute class, and its name attribute. It related to OpenTelemetry-Sdk name.

The goal, should be to have only one instance of objects which is creating this EventSource.

@open-telemetry/dotnet-approvers,
could you please rename this issue to something like: Multiple instances of EventSource for OpenTelemetry-Sdk?

What is more, it is a good candidate to fix in 1.5.0, so please assign to this milestone.

@pellared pellared changed the title Trace broken in netfx ? Multiple instances of OpenTelemetry-Sdk EventSource May 30, 2023
@pellared pellared added this to the 1.5.0 milestone May 30, 2023
@Kielek
Copy link
Contributor

Kielek commented Jun 2, 2023

We have had similar issue is automatic-instrumentation repository. The (tricky) solution: open-telemetry/opentelemetry-dotnet-instrumentation#2145

@utpilla utpilla modified the milestones: 1.5.0, 1.6.0 Jun 5, 2023
@utpilla
Copy link
Contributor

utpilla commented Jun 5, 2023

@pellared This is a bit short notice to be completed in 1.5.0. Moving it to 1.6.0.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
4 participants