search

open-telemetry / opentelemetry-dotnet-contrib

This repository contains set of components extending functionality of the OpenTelemetry .NET SDK. Instrumentation libraries, exporters, and other components can find their home here.
https://opentelemetry.io
Apache License 2.0
461 stars 276 forks source link

Receiving "Failed to inject activity context in format: 'TraceContextPropagator', context: 'Invalid context'." in ASP.NET Web Forms and MVC Autoinstrumentation #1212

Closed danielodievich closed 1 year ago

danielodievich commented 1 year ago

Summary

I have a large legacy ASP.NET Web Forms .NET 4.7 Framework application that I would like to instrument. In anticipation of this, I decided to revisit the Autoinstrumentation to see how well it works with the older style apps running on .NET 4.7 under IIS. The Autoinstrumentation works to send metrics, but fails to send traces with a repeated error in the logs.

Test Applications

I created 3 test applications using .NET 4.7.2 framework (net472):

I am hosing them in IIS:

image

Configuration of Autoinjection

I got binaries locally https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/releases/tag/v0.7.0.

I added OTEL_LOG_LEVEL=debug per https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/blob/main/docs/config.md#internal-logs to the variables set up by OpenTelemetry.DotNet.Auto.psm1 before configuring anything.

I then ran the install from the local archive:

PS > Import-Module .\OpenTelemetry.DotNet.Auto.psm1
PS > Install-OpenTelemetryCore -LocalPath ".\opentelemetry-dotnet-instrumentation-windows.zip"

The binaries are properly unpacked to C:\Program Files\OpenTelemetry .NET AutoInstrumentation and I can I can see the variables set up in the W3SVC service:

PS C:\Users\Administrator> (Get-ItemProperty HKLM:\SYSTEM\CurrentControlSet\Services\W3SVC).Environment | Sort
ASPNETCORE_HOSTINGSTARTUPASSEMBLIES=OpenTelemetry.AutoInstrumentation.AspNetCoreBootstrapper
COR_ENABLE_PROFILING=1
COR_PROFILER_PATH_32=C:\Program Files\OpenTelemetry .NET AutoInstrumentation\win-x86\OpenTelemetry.AutoInstrumentation.Native.dll
COR_PROFILER_PATH_64=C:\Program Files\OpenTelemetry .NET AutoInstrumentation\win-x64\OpenTelemetry.AutoInstrumentation.Native.dll
COR_PROFILER={918728DD-259F-4A6A-AC2B-B85E1B658318}
CORECLR_ENABLE_PROFILING=1
CORECLR_PROFILER_PATH_32=C:\Program Files\OpenTelemetry .NET AutoInstrumentation\win-x86\OpenTelemetry.AutoInstrumentation.Native.dll
CORECLR_PROFILER_PATH_64=C:\Program Files\OpenTelemetry .NET AutoInstrumentation\win-x64\OpenTelemetry.AutoInstrumentation.Native.dll
CORECLR_PROFILER={918728DD-259F-4A6A-AC2B-B85E1B658318}
DOTNET_ADDITIONAL_DEPS=C:\Program Files\OpenTelemetry .NET AutoInstrumentation\AdditionalDeps
DOTNET_SHARED_STORE=C:\Program Files\OpenTelemetry .NET AutoInstrumentation\store
DOTNET_STARTUP_HOOKS=C:\Program Files\OpenTelemetry .NET AutoInstrumentation\net\OpenTelemetry.AutoInstrumentation.StartupHook.dll
OTEL_DOTNET_AUTO_HOME=C:\Program Files\OpenTelemetry .NET AutoInstrumentation
OTEL_LOG_LEVEL=debug

OtelCol setup

I got otelcol from https://github.com/open-telemetry/opentelemetry-collector-releases/releases/tag/v0.78.0.

I configured it with this otel-collector-config.yaml:

receivers:
  otlp:
    protocols:
      grpc:
      http:

processors:
  attributes/example:
    actions:
      - key: machine_name
        value: "OBSERVEWS2022"
        action: insert
  batch:

exporters:
  logging:
    #logLevel: debug
  otlphttp:
    endpoint: "https://collect.observe-eng.com/v1/otel"
    headers:
      'Authorization': 'REDACTED'
  prometheusremotewrite:
    endpoint: "https://collect.observe-eng.com/v1/prometheus"
    headers:
      'Authorization': 'REDACTED'

extensions:
  health_check:
  pprof:
  zpages:

service:
  telemetry:
    logs:
      level: "debug"
  extensions: [health_check,pprof,zpages]
  pipelines:
    traces:
      receivers: [otlp]
      processors: [attributes/example,batch]
      exporters: [otlphttp]
    metrics:
      receivers: [otlp]
      processors: [attributes/example,batch]
      exporters: [prometheusremotewrite]
    logs:
      receivers: [otlp]
      processors: [batch]
      exporters: [logging]

I started otelcol:

.".\otelcol.exe" --config ".\otel-collector-config.yaml"

Running the test Applications

When I invoke the applications, I can see the OpenTelemetry Autoingestion kick in (the agent asseblies show up in in the list of loaded dlls in the w3wp) and the logs in C:\ProgramData\OpenTelemetry .NET AutoInstrumentation\logs begin populating.

Metrics are Flowing great

I see this in logs and immediately start seeing metrics sent to my service by otelcol:

[2023-05-30T00:05:10.9921335Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'OpenTelemetry.Exporter.OtlpMetricExporter.Export succeeded.' 
[2023-05-30T00:05:10.9971338Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'ProcessMetrics succeeded.' 
[2023-05-30T00:05:10.9991872Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'MetricReader.Collect succeeded.' 
[2023-05-30T00:06:10.6523332Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'PeriodicExportingMetricReader calling MetricReader.Collect because the export interval has elapsed.' 
[2023-05-30T00:06:10.6573355Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'MetricReader.Collect method called.' 
[2023-05-30T00:06:10.6603280Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'MetricReader.OnCollect called.' 
[2023-05-30T00:06:10.6683465Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'Observable instruments collected.' 
[2023-05-30T00:06:10.6723030Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'ProcessMetrics called.' 
[2023-05-30T00:06:10.6753149Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'BaseExportingMetricReader calling OpenTelemetry.Exporter.OtlpMetricExporter.Export method.' 
[2023-05-30T00:06:10.6852373Z] [Debug] EventSource=OpenTelemetry-Sdk, Message=MetricReader event: 'OpenTelemetry.Exporter.OtlpMetricExporter.Export succeeded.'

Traces are Not working

However, I am not seeing any traces. Instead, each of my applications is showing this message in the logs every 60 seconds:

  C:\ProgramData\OpenTelemetry .NET AutoInstrumentation\logs\otel-dotnet-auto-\LM\W3SVC\3\ROOT-1-133298786487107275-3556-20230529.log (20 hits)
    Line 110: [2023-05-30T00:05:10.8783479Z] [Warning] EventSource=OpenTelemetry-Api, Message=Failed to inject activity context in format: 'TraceContextPropagator', context: 'Invalid context'. 
    Line 120: [2023-05-30T00:06:10.6803450Z] [Warning] EventSource=OpenTelemetry-Api, Message=Failed to inject activity context in format: 'TraceContextPropagator', context: 'Invalid context'. 
    Line 130: [2023-05-30T00:07:10.6755857Z] [Warning] EventSource=OpenTelemetry-Api, Message=Failed to inject activity context in format: 'TraceContextPropagator', context: 'Invalid context'. 
    Line 140: [2023-05-30T00:08:10.6777436Z] [Warning] EventSource=OpenTelemetry-Api, Message=Failed to inject activity context in format: 'TraceContextPropagator', context: 'Invalid context'. 
    Line 150: [2023-05-30T00:09:10.6755576Z] [Warning] EventSource=OpenTelemetry-Api, Message=Failed to inject activity context in format: 'TraceContextPropagator', context: 'Invalid context'. 
    Line 160: [2023-05-30T00:10:10.6799468Z] [Warning] EventSource=OpenTelemetry-Api, Message=Failed to inject activity context in format: 'TraceContextPropagator', context: 'Invalid context'. 
    Line 170: [2023-05-30T00:11:10.6826194Z] [Warning] EventSource=OpenTelemetry-Api, Message=Failed to inject activity context in format: 'TraceContextPropagator', context: 'Invalid context'. 
...

OtelCol zpages

In the http://localhost:55679/debug/tracez, I am seeing only /v1/metrics and exporter/prometheusremotewrite/metrics. I am not seeing the exporter/otlphttp/traces or opentelemetry.proto.collector.trace.v1.TraceService/Export which I see from some other autoinstrumentation of a Python app elsewhere in another environment.

Logs

The logs are otel-dotnet-auto-logs.zip

Apps

HelloWorld.zip WebApplicationForOTEL.zip WebApplicationForOTEL2.zip

Expected Behavior

I'd really like Traces to automagically appear, like they are expected to.

danielodievich commented 1 year ago

I realized that I may have chosen the wrong repository to file this issue. If maintainers agree, please accept my apologies and close this issue here. Meanwhile, I have made a copy of it in https://github.com/open-telemetry/opentelemetry-dotnet-instrumentation/issues/2588.