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
475 stars 283 forks source link

[bug] Current AspNetCore integration does not correctly track client context when behind proxies that use `X-Forwarded-*` headers #2231

Open DrEsteban opened 1 month ago

DrEsteban commented 1 month ago

Component

OpenTelemetry.Instrumentation.AspNetCore

Package Version

Package Name Version
Azure.Monitor.OpenTelemetry.AspNetCore 1.3.0-beta.2
OpenTelemetry.Exporter.Console 1.9.0
OpenTelemetry.Instrumentation.AspNetCore (transitive) 1.9.0

Runtime Version

net8.0

Description

Because the current AspNetCore integration sets all request telemetry in the OnStart() method, it does not work correctly in situations where the webapp is receiving traffic behind a proxy where X-Forwarded-*-type headers are being used to forward the original ClientIP, Scheme, Path, etc.

ASP.NET includes middleware that by default will recognize:

In my case, I am running an ASP.NET8.0 app in Azure WebApps for Linux, which terminates TLS and forwards client context via headers like X-Forwarded-For, X-Forwarded-Proto, etc. I am using the Forwarded Headers Middleware to propagate those headers to the HttpContext, (which I've verified is working), but the OpenTelemetry framework is still using the original values when publishing telemetry.

Compare this with the native Application Insights SDK. If I configure OpenTelemetry and Application Insights side-by-side, sending to the same Application Insights resource, here are the request logs I see on the Azure portal:

Screenshot 2024-10-20 223114-2

As expected, there are 2 copies of each request because I'm double-logging traces with 2 frameworks. However, the OpenTelemetry version has not correctly recognized that the original client connection was over HTTPS, whereas the ApplicationInsights one has.

I believe this is because these values change after the "Activity" is started, once the Forwarded Headers Middleware kicks in. But by that time the Activity has already been created with the original values. Therefore, it would seem the only way to support that scenario would be to set/reset these values from the HttpContext in the OnStop() method as well. (Or by some other fancier means of tying into ASP.NET Core's middleware pipeline...)

Steps to Reproduce

  1. Create a standard ASP.NET8.0 app with the Azure.Monitor.OpenTelemetry.AspNetCore OpenTelemetry distro and the native Microsoft.ApplicationInsights.AspNetCore SDK: e.g.
    builder.Services.AddOpenTelemetry().UseAzureMonitor(); // Configures `AspNetCoreInstrumentation`
    builder.Services.AddApplicationInsightsTelemetry();
  2. Provision Application Insights and Azure WebApps/AppService instances in Azure.
  3. Configure APPLICATIONINSIGHTS_CONNECTION_STRING appropriately
  4. Deploy .NET app to WebApp, and make a few requests, ensuring you are using HTTPS
    • Azure WebApps will automatically add the X-Forwarded-* headers when it terminates TLS and forwards the requests to your app
      1. Open Application Insights instance > Logs tab > requests table

UPDATE: Added a comment where I provided a localhost repro: link

Expected Result

I expect to see both log messages are mostly identical, at least w.r.t. basic properties like request URL and ClientIP/Client Location.

Actual Result

Application Insights-generated log is correct, but OpenTelemetry-generated log as incorrect Scheme and ClientIP/Client Location.

Additional Context

This is somewhat related to #1786.

This has also been logged in Microsoft's distro (link), but was deemed to be a defect in the underlying SDK OpenTelemetry.Instrumentation.AspNetCore and therefore closed.

TimothyMothra commented 1 month ago

Hi @DrEsteban, Your steps to reproduce don't mention the X-Forwarded-* headers, so I want to make sure I'm fully understanding the problem.

http vs https

Can you test this with the ConsoleExporter and share the results?

x-forwarded-* headers

As a workaround, you can manually set these using the Enrich methods.

builder.Services.Configure<AspNetCoreTraceInstrumentationOptions>(options =>
{
    options.EnrichWithHttpRequest = (activity, httpRequest) =>
    {
        // get the actual IP from the header
        activity.SetTag("client.address", "10.10.10.10");
    };
});
DrEsteban commented 1 month ago

Hey @TimothyMothra!

I've gone ahead and updated my post with a small comment in the repro steps explaining where the X-Forwarded-* headers come into play.

Regarding the ConsoleExporter test, and your proposed workaround: Unfortunately that workaround didn't and can't work :( This is because the EnrichWithHttpRequest callback is still called within the OnStartActivity(), which means the clientIP/scheme hasn't been updated yet. (Because the Activity is created at the very start of processing the request, before the middleware pipeline has run.)

Here is a configuration to repro locally:

services.AddOpenTelemetry().WithTracing().WithLogging().WithMetrics();
services.ConfigureOpenTelemetryTracerProvider(b => 
    b.AddConsoleExporter()
        .AddAspNetCoreInstrumentation(o => o.EnrichWithHttpRequest = (a, context) => a.SetTag("new_scheme", context.Scheme)));

services.Configure<ForwardedHeadersOptions>(o =>
{
    // Trust forwarded headers from any IP (not secure)
    o.KnownNetworks.Add(IPNetwork.Parse("0.0.0.0/0"));
    o.AllowedHosts = ["*"];
    o.RequireHeaderSymmetry = false;
    o.ForwardedHeaders = ForwardedHeaders.All;
});

var app = builder.Build();
app.UseForwardedHeaders();
app.Use((context, next) =>
{
    context.RequestServices.GetRequiredService<ILogger<Program>>().LogInformation($"Request from {context.Request.Scheme}");
    return next(context);
});

I then issue a request with: curl http://localhost:5041 -v -H "X-Forwarded-Proto: HTTPS"

And here is the console output:

ConsoleExporter output ``` LogRecord.Timestamp: 2024-10-23T07:57:30.1888457Z LogRecord.TraceId: dc09625e4f5bb6745985befeb5e154ef LogRecord.SpanId: 402c71d05b9cdecb LogRecord.TraceFlags: Recorded LogRecord.CategoryName: Program LogRecord.Severity: Info LogRecord.SeverityText: Information LogRecord.FormattedMessage: Request from HTTPS LogRecord.Body: Request from HTTPS LogRecord.Attributes (Key:Value): OriginalFormat (a.k.a Body): Request from HTTPS LogRecord.ScopeValues (Key:Value): [Scope.0]:SpanId: 402c71d05b9cdecb [Scope.0]:TraceId: dc09625e4f5bb6745985befeb5e154ef [Scope.0]:ParentId: 0000000000000000 [Scope.1]:ConnectionId: 0HN7J71C0P6LQ [Scope.2]:RequestId: 0HN7J71C0P6LQ:00000001 [Scope.2]:RequestPath: / Resource associated with LogRecord: telemetry.sdk.name: opentelemetry telemetry.sdk.language: dotnet telemetry.sdk.version: 1.9.0 service.name: unknown_service:Redirector Activity.TraceId: dc09625e4f5bb6745985befeb5e154ef Activity.SpanId: 402c71d05b9cdecb Activity.TraceFlags: Recorded Activity.ActivitySourceName: Microsoft.AspNetCore Activity.DisplayName: GET Activity.Kind: Server Activity.StartTime: 2024-10-23T07:57:30.1275584Z Activity.Duration: 00:00:00.0884825 Activity.Tags: Environment: Development server.address: localhost server.port: 5041 http.request.method: GET url.scheme: http url.path: / network.protocol.version: 1.1 user_agent.original: curl/8.9.1 new_scheme: http http.response.status_code: 404 response: 404 Resource associated with Activity: telemetry.sdk.name: opentelemetry telemetry.sdk.language: dotnet telemetry.sdk.version: 1.9.0 ```

Notice my LogRecord, which pulls directly from context.Request.Scheme after UseForwardedHeaders() has run, is correctly reporting HTTPS. But the Activity.Tags url.scheme and new_scheme are incorrect. (The latter being the new tag I added using your suggested workaround.)

The only way I've found to truly workaround this issue is to introduce a custom Processor:

MyHttpTraceActivityProcessor.cs ```csharp public class MyHttpTraceActivityProcessor(IHttpContextAccessor _httpContextAccessor) : BaseProcessor { public override void OnEnd(Activity activity) { var context = _httpContextAccessor.HttpContext; if (context == null) { return; } // Fix Forwarded Headers... const string ClientIP = "client.address"; const string Scheme = "url.scheme"; const string Host = "server.address"; const string Port = "server.port"; const string Path = "url.path"; var request = context.Request; var connection = context.Connection; var path = (request.PathBase.HasValue || request.Path.HasValue) ? (request.PathBase + request.Path).ToString() : "/"; SetIpAddressTagIfDifferent(activity, ClientIP, connection.RemoteIpAddress?.ToString()); SetStringTagIfDifferent(activity, Scheme, request.Scheme); SetStringTagIfDifferent(activity, Host, request.Host.Host); SetIntTagIfDifferent(activity, Port, request.Host.Port); SetStringTagIfDifferent(activity, Path, path); } private static void SetIpAddressTagIfDifferent(Activity activity, string key, string? value) { if (string.IsNullOrWhiteSpace(value)) { return; } object? currentTag = activity.GetTagItem(key); if (currentTag == null) // If null, set { activity.SetTag(key, value); } else if (currentTag is string currentStr) { if (currentStr != value) // Only set if different { activity.SetTag(key, value); } } else if (currentTag is IPAddress currentAddr) { if (currentAddr.ToString() != value) // Only set if different { activity.SetTag(key, value); } } else // Unrecognized existing type { activity.SetTag(key + ".on-end-value", value); activity.SetTag(key + ".type", currentTag.GetType().FullName); } } private static void SetStringTagIfDifferent(Activity activity, string key, string? value) { if (string.IsNullOrWhiteSpace(value)) { return; } object? currentTag = activity.GetTagItem(key); if (currentTag == null) // If null, set { activity.SetTag(key, value); } else if (currentTag is string currentStr) { if (currentStr != value) // Only set if different { activity.SetTag(key, value); } } else // Unrecognized existing type { activity.SetTag(key + ".on-end-value", value); activity.SetTag(key + ".type", currentTag.GetType().FullName); } } private static void SetIntTagIfDifferent(Activity activity, string key, int? valueNullable) { if (!valueNullable.HasValue) { return; } int value = valueNullable.Value; object? currentTag = activity.GetTagItem(key); if (currentTag == null) // If null, set { activity.SetTag(key, value); } else if (currentTag is int currentInt) { if (currentInt != value) // Only set if different { activity.SetTag(key, value); } } else if (currentTag is string currentString) { if (currentString != value.ToString()) // Only set if different { activity.SetTag(key, value); } } else // Unrecognized existing type { activity.SetTag(key + ".on-end-value", value); activity.SetTag(key + ".type", currentTag.GetType().FullName); } } } ```

(That's probably a little too verbose & complex for a workaround πŸ˜† But I wanted the solution to be generic and safe lol. Hopefully it conveys the idea!)

TimothyMothra commented 1 month ago

Thank you for the extra information!

With regard to the X-Forwarded- headers,

the OpenTelemetry specification doesn't make comprehensive recommendations on how to handle these. The few parts where they are mentioned seem to suggest that they are opt-in (specification link). Since it's not required by the spec, I wouldn't expect to see any changes here in the near future.

Your custom Processor looks good and I think this would be the recommended workaround.

With regard to http vs https,

I can see the ConsoleExporter is showing url.scheme: http. This tells me that it's not an issue with any of the individual exporters, but likely a bug in the Instrumentation library. I'll need more time to investigate where this bug is.

TimothyMothra commented 1 month ago

@DrEsteban one more question, what version of .NET are you using?

Starting with .NET 8, the native libraries for AspNetCore produce their own Activities. We need to investigate if this issue affects the Instrumentation library, the native instrumentation, or both.

DrEsteban commented 1 month ago

@TimothyMothra I'm on .NET 8.0! (And I personally think it's very cool the AspNetCore libraries have adopted Activities in this way πŸ™‚ It's a neat way to handle library instrumentation.)


From the spec:

Screenshot_20241026-041033

Your comment from above:

Since it's not required by the spec, I wouldn't expect to see any changes here in the near future.

The specification does seem to call the concept out, at least X-Forwarded-Host, saying instrumentations "SHOULD" make best effort to use the correct value based on the decision tree above.

When you say it's not required by the spec, is that because of the "should" terminology? While I understand it doesn't say "must", it does seem to strongly suggest grabbing the correct value(s) - even providing an ordered priority list on where the values should come from.

So, if the SDK is going to try to set these properties at all, it feels like both the spec AND user expectation are pointing to a change that needs to be made to the current behavior. (At least in my opinion/interpretation! πŸ™‚) Of course another option would be to stop setting these properties entirely, since they are optional, but IMO I think it's a valuable behavior. It's just, if they're going to be set, they should ideally be set correctly! (To spec)

</rant> πŸ˜‰

Thanks for your attention to this issue!

onionhammer commented 1 month ago

The spec you've pasted here seems pretty unambiguous - according to that snip, there is alignment between the spec and our expectations; @TimothyMothra are you referring to some other part of the spec or a different spec?