[question] No OpenTelemetry-based tracing data captured when proxies are not instrumented

[perlun]

Package

OpenTelemetry

Package Version

Package Name	Version
OpenTelemetry.Exporter.Console	1.9.0
OpenTelemetry.Exporter.OpenTelemetryProtocol	1.9.0
OpenTelemetry.Extensions.Hosting	1.9.0
OpenTelemetry.Instrumentation.AspNetCore	1.9.0

Runtime Version

net8.0

Description

Hi,

We have been debugging a really weird problem for quite some time now, so I thought I'd reach out and ask for help. The problem is with our ASP.NET Core application not producing any tracing-related data, despite being enabled in our Startup class.

What's even more weird: the exact same application works fine when running locally (both in Docker and on the Linux host). In the deployed environment, it runs inside Docker and this is where it doesn't work.

I am not necessarily saying this is a bug in OpenTelemetry, but something in our application or elsewhere is causing the OpenTelemetry-based instrumentation to malfunction.

Steps to Reproduce

Unfortunately, I don't currently have a minimal reproducible example; in an isolated ASP.NET application based on the "getting started" example (https://opentelemetry.io/docs/languages/net/getting-started/), everything works as intended. The problem is isolated to our production code.

Setup code

We set up OpenTelemetry in a method called from ConfigureServices in our Startup class:

builder.ConfigureResource(resource => resource.AddService(serviceName, serviceVersion: serviceVersion))
    .WithTracing(tracing => {
        tracing.AddAspNetCoreInstrumentation();

        if (enableConsoleExporter) {
            tracing.AddConsoleExporter();
        }

        if (enableOtlpExporter) {
            tracing.AddOtlpExporter(exporter => {
                exporter.Protocol = protocol;
                exporter.Endpoint = protocol == OtlpExportProtocol.Grpc ? otlpEndpoint! : new Uri(Path.Combine(otlpEndpoint!.AbsoluteUri, "v1/traces"));
            });
        }
    })
    .WithMetrics(metrics => {
        metrics.AddAspNetCoreInstrumentation();

        if (enableConsoleExporter) {
            metrics.AddConsoleExporter();
        }

        if (enableOtlpExporter) {
            metrics.AddOtlpExporter(exporter => {
                exporter.Protocol = protocol;
                exporter.Endpoint = protocol == OtlpExportProtocol.Grpc ? otlpEndpoint! : new Uri(Path.Combine(otlpEndpoint!.AbsoluteUri, "v1/metrics"));
            });
        }
    })
    .WithLogging(logging => {
        logging.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService(serviceName, serviceVersion: serviceVersion));

        if (enableConsoleExporter) {
            logging.AddConsoleExporter();
        }

        if (enableOtlpExporter) {
            logging.AddOtlpExporter(exporter => {
                exporter.Protocol = protocol;
                exporter.Endpoint = protocol == OtlpExportProtocol.Grpc ? otlpEndpoint! : new Uri(Path.Combine(otlpEndpoint!.AbsoluteUri, "v1/logs")); ;
            });
        }
    });

Expected Result

Tracing data from ASP.NET being sent to the configured OTLP exporter.

Actual Result

No tracing data emitted whatsoever.

Additional Context

NuGet package references

In addition to the package versions listed above, we also tested with 1.10.0-beta.1 + 1.9.0 of OpenTelemetry.Instrumentation.AspNetCore, with no difference.

What we have tested

1. Set up the OpenTelemetry Collector using these instructions, for easy(er) debugging. Presume the name of the container is otel-collector.

2. Run the application (inside Docker). Provoke some HTTP requests that produces tracing-related data. Check the logs of the OpenTelemetry Collector using this command: docker logs otel-collector 2>&1 | grep data_type. On the environments where this doesn't work, the command outputs data roughly like this. As can be seen, no traces-related data is emitted from the application. (logs was also missing at one point but I think this was because of a misconfiguration in our app)

   2024-10-22T08:21:13.793982772Z 2024-10-22T08:21:13.792Z	info	exporter@v0.86.0/exporter.go:275	Development component. May change in the future.	{"kind": "exporter", "data_type": "metrics", "name": "debug"}
   2024-10-22T08:21:13.793988623Z 2024-10-22T08:21:13.793Z	info	exporter@v0.86.0/exporter.go:275	Development component. May change in the future.	{"kind": "exporter", "data_type": "traces", "name": "debug"}
   2024-10-22T08:21:13.793993493Z 2024-10-22T08:21:13.793Z	info	exporter@v0.86.0/exporter.go:275	Development component. May change in the future.	{"kind": "exporter", "data_type": "logs", "name": "debug"}
   2024-10-22T08:21:13.794268838Z 2024-10-22T08:21:13.794Z	warn	internal@v0.86.0/warning.go:40	Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks	{"kind": "receiver", "name": "otlp", "data_type": "metrics", "documentation": "https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks"}
   2024-10-22T08:21:13.794274178Z 2024-10-22T08:21:13.794Z	info	otlpreceiver@v0.86.0/otlp.go:83	Starting GRPC server	{"kind": "receiver", "name": "otlp", "data_type": "metrics", "endpoint": "0.0.0.0:4317"}
   2024-10-22T08:21:53.881252945Z 2024-10-22T08:21:53.881Z	info	MetricsExporter	{"kind": "exporter", "data_type": "metrics", "name": "debug", "resource metrics": 1, "metrics": 6, "data points": 21}
   2024-10-22T08:21:53.885061418Z 	{"kind": "exporter", "data_type": "metrics", "name": "debug"}
   2024-10-22T08:22:53.779940607Z 2024-10-22T08:22:53.779Z	info	MetricsExporter	{"kind": "exporter", "data_type": "metrics", "name": "debug", "resource metrics": 1, "metrics": 6, "data points": 21}
   2024-10-22T08:22:53.782534600Z 	{"kind": "exporter", "data_type": "metrics", "name": "debug"}
   2024-10-22T08:23:53.919277352Z 2024-10-22T08:23:53.919Z	info	MetricsExporter	{"kind": "exporter", "data_type": "metrics", "name": "debug", "resource metrics": 1, "metrics": 6, "data points": 21}
   2024-10-22T08:23:53.921449173Z 	{"kind": "exporter", "data_type": "metrics", "name": "debug"}
   2024-10-22T08:24:53.821307132Z 2024-10-22T08:24:53.821Z	info	MetricsExporter	{"kind": "exporter", "data_type": "metrics", "name": "debug", "resource metrics": 1, "metrics": 6, "data points": 21}
   2024-10-22T08:24:53.823646138Z 	{"kind": "exporter", "data_type": "metrics", "name": "debug"}
   2024-10-22T08:25:53.947672736Z 2024-10-22T08:25:53.947Z	info	MetricsExporter	{"kind": "exporter", "data_type": "metrics", "name": "debug", "resource metrics": 1, "metrics": 6, "data points": 21}
   2024-10-22T08:25:53.949857274Z 	{"kind": "exporter", "data_type": "metrics", "name": "debug"}
   2024-10-22T08:26:53.889353856Z 2024-10-22T08:26:53.889Z	info	MetricsExporter	{"kind": "exporter", "data_type": "metrics", "name": "debug", "resource metrics": 1, "metrics": 6, "data points": 21}
   2024-10-22T08:26:53.891587765Z 	{"kind": "exporter", "data_type": "metrics", "name": "debug"}
   

The OTEL_DIAGNOSTICS.json-generated diagnostics

When it works (on my local machine), the log looks roughly like this. The "Activity stopped" events contains the path to the route being traced (GET api/path/to/resource-1 etc).

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.
2024-10-21T10:50:51.1871373Z:LoggerProviderSdk event: '{0}'{Building LoggerProvider.}
2024-10-21T10:50:51.2765082Z:LoggerProviderSdk event: '{0}'{Completed adding processor = "Setting processor to 'SimpleLogRecordExportProcessor{ConsoleLogRecordExporter}'".}
2024-10-21T10:50:51.2765247Z:LoggerProviderSdk event: '{0}'{Using shared thread pool.}
2024-10-21T10:50:51.2774970Z:LoggerProviderSdk event: '{0}'{Completed adding processor = "Creating new composite processor and adding new processor 'BatchLogRecordExportProcessor{OtlpLogExporter}'".}
2024-10-21T10:50:51.2782023Z:LoggerProviderSdk event: '{0}'{LoggerProviderSdk built successfully.}
2024-10-21T10:50:51.3062663Z:MeterProviderSdk event: '{0}'{Building MeterProvider.}
2024-10-21T10:50:51.3217676Z:MeterProviderSdk event: '{0}'{MeterProvider configuration: {MetricLimit=1000, CardinalityLimit=2000, EmitOverflowAttribute=False, ReclaimUnusedMetricPoints=False, ExemplarFilter=, ExemplarFilterForHistograms=}.}
2024-10-21T10:50:51.3230024Z: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.)".}
2024-10-21T10:50:51.3237609Z:MeterProviderSdk event: '{0}'{Listening to following meters = "Microsoft.AspNetCore.Hosting;Microsoft.AspNetCore.Server.Kestrel;Microsoft.AspNetCore.Http.Connections;Microsoft.AspNetCore.Routing;Microsoft.AspNetCore.Diagnostics;Microsoft.AspNetCore.RateLimiting".}
2024-10-21T10:50:51.3239495Z:MeterProviderSdk event: '{0}'{Number of views configured = 0.}
2024-10-21T10:50:51.3271049Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.active_requests}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271173Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.request.duration}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271204Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.open_connections}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271213Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.connection.duration}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271221Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.request.time_in_queue}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271232Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{dns.lookup.duration}{System.Net.NameResolution}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271245Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalSuccess}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271430Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalTotalDuration.1A}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271440Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalDurationInL2Cache.1A}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271450Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalDurationInHttp.1A}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271457Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalDurationInL1CacheInUs.1B}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-21T10:50:51.3271525Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.active_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-21T10:50:51.3401436Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.active_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3404026Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.connection.duration" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-21T10:50:51.3412609Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.connection.duration" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3412907Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.rejected_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-21T10:50:51.3413595Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.rejected_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3413617Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.queued_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-21T10:50:51.3414185Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.queued_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3414202Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.queued_requests" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-21T10:50:51.3423568Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.queued_requests" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3423671Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.upgraded_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-21T10:50:51.3424598Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.upgraded_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3424619Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.tls_handshake.duration" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-21T10:50:51.3425318Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.tls_handshake.duration" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3425336Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.active_tls_handshakes" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-21T10:50:51.3426168Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.active_tls_handshakes" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3426189Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "http.server.active_requests" of Meter = "Microsoft.AspNetCore.Hosting".}
2024-10-21T10:50:51.3426741Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "http.server.active_requests" of Meter = "Microsoft.AspNetCore.Hosting" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3426757Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "http.server.request.duration" of Meter = "Microsoft.AspNetCore.Hosting".}
2024-10-21T10:50:51.3427389Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "http.server.request.duration" of Meter = "Microsoft.AspNetCore.Hosting" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.3427402Z:MeterProviderSdk event: '{0}'{MeterProvider built successfully.}
2024-10-21T10:50:51.3506205Z:TracerProviderSdk event: '{0}'{Building TracerProvider.}
2024-10-21T10:50:51.3623268Z:TracerProviderSdk event: '{0}'{Sampler added = "OpenTelemetry.Trace.ParentBasedSampler".}
2024-10-21T10:50:51.3635774Z:TracerProviderSdk event: '{0}'{Processors added = "OpenTelemetry.SimpleActivityExportProcessor;OpenTelemetry.BatchActivityExportProcessor".}
2024-10-21T10:50:51.3635853Z:TracerProviderSdk event: '{0}'{Instrumentations added = "AspNetCoreInstrumentation".}
2024-10-21T10:50:51.3639356Z:TracerProviderSdk event: '{0}'{TracerProvider built successfully.}
2024-10-21T10:50:51.7742357Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "signalr.server.connection.duration" of Meter = "Microsoft.AspNetCore.Http.Connections".}
2024-10-21T10:50:51.7743980Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "signalr.server.connection.duration" of Meter = "Microsoft.AspNetCore.Http.Connections" will be processed and aggregated by the SDK.}
2024-10-21T10:50:51.7744237Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "signalr.server.active_connections" of Meter = "Microsoft.AspNetCore.Http.Connections".}
2024-10-21T10:50:51.7746709Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "signalr.server.active_connections" of Meter = "Microsoft.AspNetCore.Http.Connections" will be processed and aggregated by the SDK.}
2024-10-21T10:50:52.2278011Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "aspnetcore.routing.match_attempts" of Meter = "Microsoft.AspNetCore.Routing".}
2024-10-21T10:50:52.2279199Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "aspnetcore.routing.match_attempts" of Meter = "Microsoft.AspNetCore.Routing" will be processed and aggregated by the SDK.}
2024-10-21T10:50:52.2283461Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "aspnetcore.diagnostics.exceptions" of Meter = "Microsoft.AspNetCore.Diagnostics".}
2024-10-21T10:50:52.2284295Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "aspnetcore.diagnostics.exceptions" of Meter = "Microsoft.AspNetCore.Diagnostics" will be processed and aggregated by the SDK.}
2024-10-21T10:51:01.9211715Z:MetricReader event: '{0}'{PeriodicExportingMetricReader calling MetricReader.Collect because the export interval has elapsed.}
2024-10-21T10:51:01.9421498Z:MetricReader event: '{0}'{MetricReader.Collect method called.}
2024-10-21T10:51:01.9426038Z:MetricReader event: '{0}'{MetricReader.OnCollect called.}
2024-10-21T10:51:01.9432354Z:MetricReader event: '{0}'{Observable instruments collected.}
2024-10-21T10:51:01.9441598Z:MetricReader event: '{0}'{ProcessMetrics called.}
2024-10-21T10:51:01.9444762Z:MetricReader event: '{0}'{BaseExportingMetricReader calling OpenTelemetry.Exporter.ConsoleMetricExporter.Export method.}
2024-10-21T10:51:01.9494475Z:MetricReader event: '{0}'{OpenTelemetry.Exporter.ConsoleMetricExporter.Export succeeded.}
2024-10-21T10:51:01.9494540Z:MetricReader event: '{0}'{ProcessMetrics succeeded.}
2024-10-21T10:51:01.9494980Z:MetricReader event: '{0}'{MetricReader.Collect succeeded.}
2024-10-21T10:51:11.3156003Z:MetricReader event: '{0}'{PeriodicExportingMetricReader calling MetricReader.Collect because the export interval has elapsed.}
2024-10-21T10:51:11.3156559Z:MetricReader event: '{0}'{MetricReader.Collect method called.}
2024-10-21T10:51:11.3156651Z:MetricReader event: '{0}'{MetricReader.OnCollect called.}
2024-10-21T10:51:11.3157810Z:MetricReader event: '{0}'{Observable instruments collected.}
2024-10-21T10:51:11.3157961Z:MetricReader event: '{0}'{ProcessMetrics called.}
2024-10-21T10:51:11.3157975Z:MetricReader event: '{0}'{BaseExportingMetricReader calling OpenTelemetry.Exporter.ConsoleMetricExporter.Export method.}
2024-10-21T10:51:11.3158055Z:MetricReader event: '{0}'{OpenTelemetry.Exporter.ConsoleMetricExporter.Export succeeded.}
2024-10-21T10:51:11.3158066Z:MetricReader event: '{0}'{ProcessMetrics succeeded.}
2024-10-21T10:51:11.3158104Z:MetricReader event: '{0}'{MetricReader.Collect succeeded.}
2024-10-21T10:51:17.4389198Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-d16b76cdaaae40558a4aa9e075629538-72eac02c6d49bdf4-01}
2024-10-21T10:51:17.6677603Z:Activity stopped. Name = '{0}', Id = '{1}'.{GET api/path/to/resource-1}{00-d16b76cdaaae40558a4aa9e075629538-72eac02c6d49bdf4-01}
2024-10-21T10:51:17.7311606Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-5c4c4143b78f1bce4c6f436827308824-cb36888656b7c033-01}
2024-10-21T10:51:17.7345445Z:Activity stopped. Name = '{0}', Id = '{1}'.{OPTIONS api/path/to/resource-2}{00-5c4c4143b78f1bce4c6f436827308824-cb36888656b7c033-01}
2024-10-21T10:51:17.7357012Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-29c32bfc704e861e3d9c83ba2077c193-7443b4a57dacdba4-01}
2024-10-21T10:51:18.0706066Z:Activity stopped. Name = '{0}', Id = '{1}'.{GET api/path/to/resource-3}{00-29c32bfc704e861e3d9c83ba2077c193-7443b4a57dacdba4-01}

When it doesn't work, it looks like this. Note how the Activity stopped entries are lacking the URL paths.

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.
2024-10-23T06:04:08.9376626Z:LoggerProviderSdk event: '{0}'{Building LoggerProvider.}
2024-10-23T06:04:08.9670148Z:LoggerProviderSdk event: '{0}'{Using shared thread pool.}
2024-10-23T06:04:08.9670980Z:LoggerProviderSdk event: '{0}'{Completed adding processor = "Setting processor to 'BatchLogRecordExportProcessor{OtlpLogExporter}'".}
2024-10-23T06:04:08.9675341Z:LoggerProviderSdk event: '{0}'{LoggerProviderSdk built successfully.}
2024-10-23T06:04:09.0096817Z:MeterProviderSdk event: '{0}'{Building MeterProvider.}
2024-10-23T06:04:09.0155556Z:MeterProviderSdk event: '{0}'{MeterProvider configuration: {MetricLimit=1000, CardinalityLimit=2000, EmitOverflowAttribute=False, ReclaimUnusedMetricPoints=False, ExemplarFilter=, ExemplarFilterForHistograms=}.}
2024-10-23T06:04:09.0157135Z:MeterProviderSdk event: '{0}'{Exporters added = "OpenTelemetry.Exporter.OtlpMetricExporter (Paired with PeriodicExportingMetricReader exporting at 60000 milliseconds intervals.)".}
2024-10-23T06:04:09.0160568Z:MeterProviderSdk event: '{0}'{Listening to following meters = "Microsoft.AspNetCore.Hosting;Microsoft.AspNetCore.Server.Kestrel;Microsoft.AspNetCore.Http.Connections;Microsoft.AspNetCore.Routing;Microsoft.AspNetCore.Diagnostics;Microsoft.AspNetCore.RateLimiting".}
2024-10-23T06:04:09.0163922Z:MeterProviderSdk event: '{0}'{Number of views configured = 0.}
2024-10-23T06:04:09.0188581Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.active_requests}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188657Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.request.duration}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188676Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.open_connections}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188689Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.connection.duration}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188703Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{http.client.request.time_in_queue}{System.Net.Http}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188721Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{dns.lookup.duration}{System.Net.NameResolution}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188737Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalSuccess}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188751Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalTotalDuration.1A}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188919Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalDurationInL2Cache.1A}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188936Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalDurationInHttp.1A}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188950Z:Measurements from Instrument '{0}', Meter '{1}' will be ignored. Reason: '{2}'. Suggested action: '{3}'{MsalDurationInL1CacheInUs.1B}{MicrosoftIdentityClient_Common_Meter}{Instrument belongs to a Meter not subscribed by the provider.}{Use AddMeter to add the Meter to the provider.}
2024-10-23T06:04:09.0188985Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.active_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-23T06:04:09.0273482Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.active_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0283254Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.connection.duration" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-23T06:04:09.0290079Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.connection.duration" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0290164Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.rejected_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-23T06:04:09.0290438Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.rejected_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0290466Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.queued_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-23T06:04:09.0290686Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.queued_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0290751Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.queued_requests" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-23T06:04:09.0290908Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.queued_requests" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0290929Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.upgraded_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-23T06:04:09.0291097Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.upgraded_connections" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0291117Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.tls_handshake.duration" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-23T06:04:09.0291321Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.tls_handshake.duration" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0291342Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "kestrel.active_tls_handshakes" of Meter = "Microsoft.AspNetCore.Server.Kestrel".}
2024-10-23T06:04:09.0291492Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "kestrel.active_tls_handshakes" of Meter = "Microsoft.AspNetCore.Server.Kestrel" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0291515Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "http.server.active_requests" of Meter = "Microsoft.AspNetCore.Hosting".}
2024-10-23T06:04:09.0291784Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "http.server.active_requests" of Meter = "Microsoft.AspNetCore.Hosting" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0291831Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "http.server.request.duration" of Meter = "Microsoft.AspNetCore.Hosting".}
2024-10-23T06:04:09.0292049Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "http.server.request.duration" of Meter = "Microsoft.AspNetCore.Hosting" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.0292068Z:MeterProviderSdk event: '{0}'{MeterProvider built successfully.}
2024-10-23T06:04:09.0362738Z:TracerProviderSdk event: '{0}'{Building TracerProvider.}
2024-10-23T06:04:09.0447767Z:TracerProviderSdk event: '{0}'{Sampler added = "OpenTelemetry.Trace.ParentBasedSampler".}
2024-10-23T06:04:09.0455398Z:TracerProviderSdk event: '{0}'{Processors added = "OpenTelemetry.BatchActivityExportProcessor".}
2024-10-23T06:04:09.0455445Z:TracerProviderSdk event: '{0}'{Instrumentations added = "AspNetCoreInstrumentation".}
2024-10-23T06:04:09.0462356Z:TracerProviderSdk event: '{0}'{TracerProvider built successfully.}
2024-10-23T06:04:09.2975480Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "signalr.server.connection.duration" of Meter = "Microsoft.AspNetCore.Http.Connections".}
2024-10-23T06:04:09.2976053Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "signalr.server.connection.duration" of Meter = "Microsoft.AspNetCore.Http.Connections" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.2976270Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "signalr.server.active_connections" of Meter = "Microsoft.AspNetCore.Http.Connections".}
2024-10-23T06:04:09.2976828Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "signalr.server.active_connections" of Meter = "Microsoft.AspNetCore.Http.Connections" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.6347414Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "aspnetcore.routing.match_attempts" of Meter = "Microsoft.AspNetCore.Routing".}
2024-10-23T06:04:09.6348030Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "aspnetcore.routing.match_attempts" of Meter = "Microsoft.AspNetCore.Routing" will be processed and aggregated by the SDK.}
2024-10-23T06:04:09.6354436Z:MeterProviderSdk event: '{0}'{Started publishing Instrument = "aspnetcore.diagnostics.exceptions" of Meter = "Microsoft.AspNetCore.Diagnostics".}
2024-10-23T06:04:09.6354893Z:MeterProviderSdk event: '{0}'{Measurements for Instrument = "aspnetcore.diagnostics.exceptions" of Meter = "Microsoft.AspNetCore.Diagnostics" will be processed and aggregated by the SDK.}
2024-10-23T06:04:28.9801946Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-2fc3ac247eb6468b1abe4867f7d8f5a0-3d9f1360241c008b-00}
2024-10-23T06:04:29.3651212Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-2fc3ac247eb6468b1abe4867f7d8f5a0-3d9f1360241c008b-00}
2024-10-23T06:04:50.6735629Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-5d84a8280163e87335566d57c4596d05-cd5dfb4948e3d22b-00}
2024-10-23T06:04:51.1688283Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-5d84a8280163e87335566d57c4596d05-cd5dfb4948e3d22b-00}
2024-10-23T06:04:52.3053712Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-c9fca2685a6bedd13e87e7e754e1ff0c-10e65782ab8a2a55-00}
2024-10-23T06:04:52.3571307Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-c9fca2685a6bedd13e87e7e754e1ff0c-10e65782ab8a2a55-00}
2024-10-23T06:04:52.4284638Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-af32c8a2aeb681d57040924b58df22dd-1da8b0bf55daaf49-00}
2024-10-23T06:04:52.4512005Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-af32c8a2aeb681d57040924b58df22dd-1da8b0bf55daaf49-00}
2024-10-23T06:04:52.5381280Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-3967d4aa6a094105f89879f9de124772-3878a1829dbcb5c0-00}
2024-10-23T06:04:52.5487355Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-3967d4aa6a094105f89879f9de124772-3878a1829dbcb5c0-00}
2024-10-23T06:04:53.3421831Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-37cfff3982eb789194df5435a4f6f065-b4ff1e090b56df79-00}
2024-10-23T06:04:53.3454200Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-f9decc4e68077fc68af5834e90c330d4-f2cbf57ac8771fba-00}
2024-10-23T06:04:53.3519818Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-37cfff3982eb789194df5435a4f6f065-b4ff1e090b56df79-00}
2024-10-23T06:04:53.4018231Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-140bcb21677e2d35d7f929abb9d6b336-48bc02a01122a1db-00}
2024-10-23T06:04:53.4348525Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-140bcb21677e2d35d7f929abb9d6b336-48bc02a01122a1db-00}
2024-10-23T06:04:53.4933301Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-72072daef1245384d4c19a31df554c0c-295dd52ec4d37589-00}
2024-10-23T06:04:53.5230513Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-72072daef1245384d4c19a31df554c0c-295dd52ec4d37589-00}
2024-10-23T06:04:53.5903825Z:Activity started. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-8e51dd8143b8200de60704893e0a63a4-0afb470773c7e694-00}
2024-10-23T06:04:54.3247869Z:Activity stopped. Name = '{0}', Id = '{1}'.{Microsoft.AspNetCore.Hosting.HttpRequestIn}{00-8e51dd8143b8200de60704893e0a63a4-0afb470773c7e694-00}

More details

I've debugged this to the best of my ability, and I suspected that the if (this.IsEnabled(EventLevel.Verbose, EventKeywords.All)) call here returned false:

opentelemetry-dotnet/src/OpenTelemetry/Internal/OpenTelemetrySdkEventSource.cs

Lines 61 to 65 in 5dff99f

	[NonEvent]
	public void ActivityStarted(Activity activity)
	{
	if (this.IsEnabled(EventLevel.Verbose, EventKeywords.All))
	{

Because of limitations in my IDE, I was unable to place a breakpoint in 3rd party code when attaching to the process running inside the Docker container on the machine where we saw the problem, so I couldn't confirm this. Also, now when writing this, I am thinking: if the event source is somehow disabled, would we even get any Activity started events being logged at all? 🤔

I am very much at the end of the road here; we don't know how to debug this further. Any ideas/suggestions are greatly appreciated. 🙏

[perlun]

I got another idea when writing the issue: enabling the console exporter for tracing only, and see what it emits. Here's the outcome:

On the deployed environment

No output whatsoever (when looking with docker logs -f <container>), apart from some Microsoft.AspNetCore and Startup.cs-based logging on app startup.

In the local environment

In addition to the above logging (and some other more detailed logging in general, enabled via appsettings.Development.json), activity tracing output is properly logged to the console:

Activity.TraceId:            9e1617832d938d791854f973cb6d2d25
Activity.SpanId:             613b6f5b1fd87116
Activity.TraceFlags:         Recorded
Activity.ActivitySourceName: Microsoft.AspNetCore
Activity.DisplayName:        GET api/path/to/resource-1
Activity.Kind:               Server
Activity.StartTime:          2024-10-23T06:44:37.3324209Z
Activity.Duration:           00:00:00.0167533
Activity.Tags:
    [...]

Will update the issue title accordingly. The problem seems to be with collection of tracing activity data in general; it's not isolated to the OTLP exporter per se.

[perlun]

For the record, we haven't found the exact source of this but... modifying our YARP-based reverse proxy which sits in front of the application makes things work. 🤯 I.e. adding basically this to our reverse proxy code:

builder.Services.AddOpenTelemetry()
    .ConfigureResource(resource => resource.AddService(serviceName))
    .WithTracing(tracing => tracing
        .AddAspNetCoreInstrumentation()
        .AddOtlpExporter()
    );

...makes OTLP tracing work (with some caveats) both for the reverse proxy and for the service behind the reverse proxy. 🤔 I'm utterly perplexed by this. Could AddAspNetCoreInstrumentation() cause the proxied traffic to be modified somehow? Some HTTP header being added/removed? I really don't know. I guess we could tpcdump the traffic between the proxy and the API backend if we're really eager, but I don't feel so inclined at the moment. 🙂

Will close this issue soon unless anyone wants to keep it open for further debugging.

[Kielek]

@perlun, I suppose that your proxy was creating non-recorded span. Then it was propagated to the application.
Keep in mind that default Sampler is ParentBased(AlwaysOn).

What is more, AspNetCore is by default instrumented - so if you do not record Activities by .AddAspNetCoreInstrumentation() it will produce non-reocrded spans.

[perlun]

@Kielek Ah, that makes a bit of sense, thanks for the reply. 👍 I'll readily admit that I'm pretty much of a noob when it comes to OpenTelemetry in general. I guess the ParentBased-stuff is documented somewhere?

[Kielek]

Sure: https://github.com/open-telemetry/opentelemetry-specification/blob/v1.38.0/specification/trace/sdk.md#built-in-samplers

[cijothomas]

Sure: https://github.com/open-telemetry/opentelemetry-specification/blob/v1.38.0/specification/trace/sdk.md#built-in-samplers

https://github.com/open-telemetry/opentelemetry-dotnet/tree/main/docs/trace/customizing-the-sdk#samplers

[perlun]

Thank @Kielek and @cijothomas. 👍 I feel like it would be worth mentioning these semantics somewhere. At least to me/us, it was quite a bit of a gotcha. We spent literal days debugging this before we (more or less by coincidence) found that it suddenly started working when we added telemetry to our Yarp-based reverse proxy. It would be nice to help others avoiding falling into this pit.

We could add it to https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry/README.md#troubleshooting, but it's a very specific problem so not sure that it properly belongs there. I guess there isn't any form of a "FAQ" for the project or similar?

[a35506322]

Hey Bro!　@perlun

You're great, I've been struggling with this problem for a whole day, I'm programmed with Client -> YARP -> Nginx -> APP.
However, after testing my Nginx and APP, I have no problem with telemetry, but only with YARP.
Just add the opentelemetry service to YARP, thank you very much!
I'll look into the Sampler @Kielek mentioned and be thankful.

[Kielek]

@perlun, @a35506322 if you think that it is worth to improve documentation, we are always opened, especially for the PRs :- ).