OpenTracingShim generate span with invalid spanContext for custom instrumentaion #2787

yehaotian · 2022-01-13T23:36:16Z

Bug Report

List of NuGet packages and
version that you are using:

OpenTelemetry.Shims.OpenTracing 1.0.0-rc8
OpenTelemetry.Extensions.Hosting 1.0.0-rc8
OpenTelemetry.Exporter.OpenTelemetryProtocol 1.2.0-rc1
OpenTracing.Contrib.NetCore 0.8.0

Runtime version:
netcoreapp3.1

Symptom

We are using our own instrumentations/diagnostics to build spans for specific activities.
Static TracerShim:

var openTelemetry = Sdk.CreateTracerProviderBuilder()
                .AddSource("Test.Tracing")
                .SetResourceBuilder(ResourceBuilder.CreateDefault()
                    .AddService(serviceName: "Test_ServiceName", serviceVersion: "Test_Version"))
                .AddOtlpExporter(opt =>
                {
                    opt.Endpoint = new Uri(INTERNAL_URI);
                    opt.Headers = "TOKEN=INTERNAL_TOKEN";
                })
                .Build();

            return new TracerShim(openTelemetry.GetTracer("Test.Tracing"), Propagators.DefaultTextMapPropagator);
        }

Custom diagnostics:

case "Microsoft.AspNetCore.Mvc.BeforeAction":
                    {
                        var httpContext = (HttpContext)_BeforeActionHttpContextFetcher.Fetch(untypedArg);
                        var request = httpContext.Request;
                        ISpanContext extractedSpanContext =  Tracer.Extract(BuiltinFormats.HttpHeaders,
                                new RequestHeadersExtractAdapter(request.Headers));

                        var operationName = _Options.Hosting.HttpOperationNameResolver(httpContext);
                        var actionScope = Tracer.BuildSpan(operationName)
                            .AsChildOf(extractedSpanContext)
                            .WithTag(TracingTags.HttpMethod, request.Method)
                            .WithTag(TracingTags.SpanKind, TracingTags.SpanKindServer)
                            .WithTag(TracingTags.Scheme, request.Scheme)
                            .WithTag(TracingTags.Path, request.Path.Value)
                            .WithTag(TracingTags.Host, request.Host.Value) 
                            .StartActive();

                        httpContext.Items[ActionScopeItemsKey] = actionScope;
                    }
                    break;

What is the expected behavior?
The generated span will have valid spanContext in SpanContextShim. And related spans can be created successfully.

What is the actual behavior?
The span contains empty fields for context which will cause Passed span's context is not valid ArgumentException when build other child spans for other activities. And no span get created successfully.

Printed span info:

"rootSpan": {
  "context": {
   "spanContext": {
    "traceId": {},
    "spanId": {},
    "traceFlags": 0,
    "isRemote": false,
    "isValid": true,
    "traceState": []
   },
   "traceId": "0828ca1eb896547a61504c4ffcfbd397",
   "spanId": "84647169dea59879"
  }
...
 }

Reproduce

Since we are leveraging same design as OpenTracing.Contrib.NetCore, we can use the project directly with opentelemetry-dotnet/examples/AspNetCore for reproducing the issue.
<PackageReference Include="OpenTracing.Contrib.NetCore" Version="0.8.0" />

In Startup.cs:

services.AddOpenTelemetryTracing((builder) => builder
                    .AddSource("Test.Tracing")
                    .SetResourceBuilder(ResourceBuilder.CreateDefault()
                        .AddService(serviceName: "test-name", serviceVersion: "test-version"))
                    .AddOtlpExporter(opt =>
                    {
                        opt.Endpoint = new Uri(INTERNAL_URI);
                        opt.Headers = "TOKEN=INTERNAL_TOKEN";
                    })
            );
            services.AddSingleton<ITracer>(provider =>
            {
                var traceProvider = provider.GetRequiredService<TracerProvider>();
                var tracer = traceProvider.GetTracer("Test.Tracing");
                var tracerShim = new TracerShim(tracer, Propagators.DefaultTextMapPropagator);
                GlobalTracer.Register(tracerShim);
                return tracerShim;
            });
            services.AddOpenTracing();

Warning when running the program:

warn: OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics[0]
      Event-Exception: Microsoft.AspNetCore.Mvc.BeforeActionResult
System.ArgumentException: Passed span's context is not valid (Parameter 'Context')
   at OpenTelemetry.Shims.OpenTracing.SpanShim..ctor(TelemetrySpan span)
   at OpenTelemetry.Shims.OpenTracing.SpanBuilderShim.Start()
   at OpenTelemetry.Shims.OpenTracing.SpanBuilderShim.StartActive(Boolean finishSpanOnDispose)
   at OpenTelemetry.Shims.OpenTracing.SpanBuilderShim.StartActive()
   at OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics.HandleEvent(String eventName, Object untypedArg)
   at OpenTracing.Contrib.NetCore.Internal.DiagnosticEventObserver.System.IObserver<System.Collections.Generic.KeyValuePair<System.String,System.Object>>.OnNext(KeyValuePair`2 value)

Additional Context

We are sending data to Lighstep with internal configuration.
Also because of OpenTracing ITracer API results in broken and multiple traces when using the AspNetCore instrumentation #2257 we cannot create any span within the application, for example create span in Controller.

The text was updated successfully, but these errors were encountered:

MMartyn · 2023-06-20T15:23:38Z

It isn't clear to me, is this issue still an open issue or was it resolved with this

pjanotti · 2023-06-27T03:30:51Z

Hi @MMartyn - when I submitted the PR that you linked I didn't have a chance to directly verify if this specific issue was resolved by it. So I was hesitant to close the issue. My understanding at the time was that this one should have been fixed by it.

@yehaotian could you let's know if the issue is resolved for you?

yehaotian · 2023-06-27T17:35:47Z

Thanks for the response, will try find some time to update the environment and do the test

yehaotian · 2023-06-27T23:34:55Z

Hi @pjanotti and @MMartyn, I updated all OpenTelemetry.* versions and still get the error.
Steps:

Follow https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/examples/Console/TestOpenTracingShim.cs to initialize shim tracer
Apply the changes and use shim tracer to generate spans in https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/examples/AspNetCore/Controllers/WeatherForecastController.cs

Getting error:

fail: Microsoft.AspNetCore.Server.Kestrel[13]
      Connection id "0HMRNCH75LCI6", Request id "0HMRNCH75LCI6:00000002": An unhandled exception was thrown by the application.
      System.ArgumentException: Invalid 'SpanContext' (Parameter 'Context')
         at OpenTelemetry.Shims.OpenTracing.SpanShim..ctor(TelemetrySpan span)
         at OpenTelemetry.Shims.OpenTracing.SpanBuilderShim.Start()
         at OpenTelemetry.Shims.OpenTracing.SpanBuilderShim.StartActive(Boolean finishSpanOnDispose)
         at getting_started.WeatherForecastController.Get() in /Users/ytian/RiderProjects/openTelemetry-sandbox/OpenTelemetrySandbox/OtelTracingSandbox/WeatherForecastController.cs:line 73
         at lambda_method2(Closure , Object , Object[] )
         at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
      --- End of stack trace from previous location ---
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
      --- End of stack trace from previous location ---
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
         at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
         at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
         at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
         at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
         at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
LogRecord.Timestamp:               2023-06-27T23:34:09.4026690Z
LogRecord.TraceId:                 1a1eb2abeb10dacabf485d0eba72c236
LogRecord.SpanId:                  47d1faa5a84392d4
LogRecord.TraceFlags:              None
LogRecord.CategoryName:            Microsoft.AspNetCore.Server.Kestrel
LogRecord.LogLevel:                Error
LogRecord.FormattedMessage:        Connection id "0HMRNCH75LCI6", Request id "0HMRNCH75LCI6:00000002": An unhandled exception was thrown by the application.
LogRecord.Body:                    Connection id "{ConnectionId}", Request id "{TraceIdentifier}": An unhandled exception was thrown by the application.
LogRecord.Attributes (Key:Value):
    ConnectionId: 0HMRNCH75LCI6
    TraceIdentifier: 0HMRNCH75LCI6:00000002
    OriginalFormat (a.k.a Body): Connection id "{ConnectionId}", Request id "{TraceIdentifier}": An unhandled exception was thrown by the application.
LogRecord.EventId:                 13
LogRecord.EventName:               ApplicationError
LogRecord.Exception:               System.ArgumentException: Invalid 'SpanContext' (Parameter 'Context')
   at OpenTelemetry.Shims.OpenTracing.SpanShim..ctor(TelemetrySpan span)
   at OpenTelemetry.Shims.OpenTracing.SpanBuilderShim.Start()
   at OpenTelemetry.Shims.OpenTracing.SpanBuilderShim.StartActive(Boolean finishSpanOnDispose)
   at getting_started.WeatherForecastController.Get() in /Users/ytian/RiderProjects/openTelemetry-sandbox/OpenTelemetrySandbox/OtelTracingSandbox/WeatherForecastController.cs:line 73
   at lambda_method2(Closure , Object , Object[] )
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
   at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)

MMartyn · 2023-06-28T00:13:02Z

I also get the same error and was just trying to confirm if it was just me.

pjanotti · 2023-06-28T03:58:31Z

Thanks @MMartyn and @yehaotian for confirming. The behavior is triggered if there are no listeners for the activity source associated to the registered OpenTracing tracer. Here is an example of the workaround:

// Add OTel
builder.Services.AddOpenTelemetry()
    .WithTracing(tracing => tracing
        .AddAspNetCoreInstrumentation()
        .AddConsoleExporter()
        .AddSource("OpenTracing")); // <- Adding the source of the OpenTracing shim

// Add OpenTracing
ITracer otTracer = new TracerShim(
    TracerProvider.Default.GetTracer("OpenTracing"),
    Propagators.DefaultTextMapPropagator);
OpenTracing.Util.GlobalTracer.Register(otTracer);

Anyway, it shouldn't hit an exception if there are no listeners for the OT shim. So this is still a bug.

yehaotian · 2023-06-28T22:27:26Z

I still get error when DO NOT have .AddAspNetCoreInstrumentation(), what could be the root cause?
Also does "OpenTracing" have to be the source name? Thought this could be customized

pjanotti · 2023-06-28T23:14:53Z

Also does "OpenTracing" have to be the source name?

No, you should be able to customize it.

pjanotti · 2023-06-28T23:22:53Z

I still get error when DO NOT have .AddAspNetCoreInstrumentation(), what could be the root cause?

The problem is that OpenTracing shim is broken if there is no parent activity. It is related to other problem in the sense that they hit the same exception, but, likely need two different fixes: one for "no listeners" and another to correctly handle root span.

I will take a look at the code to see if I can quickly fix both issues.

yehaotian · 2023-06-28T23:43:49Z

That makes sense!
Thank you for working on this!

MMartyn · 2023-06-29T00:54:09Z

Just want to report back that the workaround to add the source worked for me. Thanks.

yehaotian · 2023-07-11T17:44:27Z

Hi @pjanotti , just want to double check if there is ETA/timeline on the issue fix, we would like to migrate from OpenTracing to OpenTelemetry in this Q and this is a blocker.
Thanks!

pjanotti · 2023-07-12T17:07:42Z

Hi @yehaotian, I was on a short vacation. I will debug this issue this week or the next.

pjanotti · 2023-07-19T01:13:17Z

In the comments above there were two paths in which the issue was hit:

Missing the corresponding AddSource for the tracer used by the shim. In this case, the TelemetrySpan.NoopInstance is used when trying to create the OTel span from an OTel tracer that has no listeners.
When the AddSource is present, but, AddAspNetCoreInstrumentation was omitted we are getting a root span from AspNetCore that is not recorded, this causes the TelemetrySpan.NoopInstance to be used and once again hit the exception.

It seems that the shim should not consider an invalid span context an error condition.

A related issue is that ScopeManager.Activate also has trouble with the TelemetrySpan.NoopInstance since the no-op is a singleton and internally the shim uses a ConditionalWeakTable.

I started coding some integration tests for the shim, the proposed fix itself is trivial.

sasha-khadasevich · 2023-08-04T11:00:51Z

Hi
When it will be included to release?

Kielek · 2023-08-07T04:46:06Z

@sasha-khadasevich, fix from #4668 should be included in next 1.6.0-something release.

Other parts related to

are not fixed yet there is no ETA.

yehaotian · 2023-08-11T18:18:23Z

@Kielek @pjanotti Thanks for the efforts, let us know when 1.6.0-* get released

yehaotian added the bug Something isn't working label Jan 13, 2022

github-actions bot added the Stale Issues and pull requests which have been flagged for closing due to inactivity label Jan 25, 2022

cijothomas removed the Stale Issues and pull requests which have been flagged for closing due to inactivity label Jan 27, 2022

pjanotti mentioned this issue Aug 3, 2022

Fix OpenTracing shim under legacy AspNetCore activities #3506

Merged

1 task

pjanotti mentioned this issue Jul 19, 2023

Opentracing shim noop cases #4668

Merged

3 tasks

alanwest closed this as completed in #4668 Jul 21, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

OpenTracingShim generate span with invalid spanContext for custom instrumentaion #2787

OpenTracingShim generate span with invalid spanContext for custom instrumentaion #2787

yehaotian commented Jan 13, 2022 •

edited

Loading

MMartyn commented Jun 20, 2023

pjanotti commented Jun 27, 2023 •

edited

Loading

yehaotian commented Jun 27, 2023

yehaotian commented Jun 27, 2023

MMartyn commented Jun 28, 2023

pjanotti commented Jun 28, 2023

yehaotian commented Jun 28, 2023

pjanotti commented Jun 28, 2023

pjanotti commented Jun 28, 2023

yehaotian commented Jun 28, 2023

MMartyn commented Jun 29, 2023

yehaotian commented Jul 11, 2023

pjanotti commented Jul 12, 2023

pjanotti commented Jul 19, 2023

sasha-khadasevich commented Aug 4, 2023

Kielek commented Aug 7, 2023

yehaotian commented Aug 11, 2023

OpenTracingShim generate span with invalid spanContext for custom instrumentaion #2787

OpenTracingShim generate span with invalid spanContext for custom instrumentaion #2787

Comments

yehaotian commented Jan 13, 2022 • edited Loading

Bug Report

Symptom

Reproduce

Additional Context

MMartyn commented Jun 20, 2023

pjanotti commented Jun 27, 2023 • edited Loading

yehaotian commented Jun 27, 2023

yehaotian commented Jun 27, 2023

MMartyn commented Jun 28, 2023

pjanotti commented Jun 28, 2023

yehaotian commented Jun 28, 2023

pjanotti commented Jun 28, 2023

pjanotti commented Jun 28, 2023

yehaotian commented Jun 28, 2023

MMartyn commented Jun 29, 2023

yehaotian commented Jul 11, 2023

pjanotti commented Jul 12, 2023

pjanotti commented Jul 19, 2023

sasha-khadasevich commented Aug 4, 2023

Kielek commented Aug 7, 2023

yehaotian commented Aug 11, 2023

yehaotian commented Jan 13, 2022 •

edited

Loading

pjanotti commented Jun 27, 2023 •

edited

Loading