search

open-telemetry / opentelemetry-dotnet

The OpenTelemetry .NET Client
https://opentelemetry.io
Apache License 2.0
3.21k stars 759 forks source link

ActivityProcessor Start method invoked before custom http request property is set #1208

Closed christopher-taormina-zocdoc closed 4 years ago

christopher-taormina-zocdoc commented 4 years ago

Bug Report

Packages:

Runtime version aspnetcore2.1

Symptom

I've implemented a simple Activity Processor just like the one in the AspNetCore Instrumentation readme here. The code for the processor is as follows:

public class MyActivityProcessor : ActivityProcessor
    {
        public override void OnStart(Activity activity)
        {
            // Retrieve the HttpRequest object.
            if (activity.GetCustomProperty("OTel.AspNetCore.Request") is HttpRequest httpRequest)
            {
                // Add more tags to the activity
                activity.SetTag("mycustomtag", httpRequest.Headers["myheader"]);
            }
        }
        public override void OnEnd(Activity activity)
        {
            // Retrieve the HttpResponse object.
            if (activity.GetCustomProperty("OTel.AspNetCore.Response") is HttpResponse httpResponse)
            {
                var statusCode = httpResponse.StatusCode;
                bool success = statusCode < 400;
                // Add more tags to the activity or replace an existing tag.
                activity.SetTag("myCustomSuccess", success);
            }
        }
    }

The server is set up for otel with the following code:

collection.AddOpenTelemetryTracerProvider((otelBuilder) =>
                        {
                            otelBuilder
                                .AddSource("ServiceName")
                                .SetResource(Resources.CreateServiceResource("ServiceName"))
                                .SetSampler(new ParentBasedSampler(new TraceIdRatioBasedSampler(1)))
                                .AddAspNetCoreInstrumentation((options) =>
                                {
                                    options.Propagator = new B3Propagator();
                                })
                                .AddZipkinExporter((o) =>
                                {
                                    o.ServiceName = "ServiceName";
                                    o.Endpoint = "http://zipkinendpoint:9411/api/v2/spans";
                                })
                                .AddProcessor(new MyActivityProcessor());
                        });

When debugging through a request sent to the server, it seems the custom property for the http request is not on the Activity yet. It seems that the Start function of the activity processors is running before this property has been set. My hunch is that this line needs to move down to the end of the OnStartActivity function in the HttpInListener class.

As a workaround until this is fixed, any code interacting with the http request can just be put in the OnStop method of the ActivityProcessor.

What is the expected behavior?

The http request to exist on the activity

What is the actual behavior?

The activity does not contain the http request.

Reproduce

Create a self-contained project using the template of your choice, apply the minimum required code to result in the issue you're observing.

We will close this issue if:

Additional Context

Add any other context about the problem here.

cijothomas commented 4 years ago

.AddProcessor(new MyActivityProcessor()); must be added before the exporter. Can you try that? (I have added the importance of order in AspNet doc PR now. Will be extending it to all docs soon)

christopher-taormina-zocdoc commented 4 years ago

@cijothomas I just gave that a try and still seem to run into the same issue.

collection.AddOpenTelemetryTracerProvider((otelBuilder) =>
                        {
                            otelBuilder
                                .AddSource("ServiceName")
                                .SetResource(Resources.CreateServiceResource("ServiceName"))
                                .SetSampler(
                                    new ParentBasedSampler(new TraceIdRatioBasedSampler(1)))
                                .AddAspNetCoreInstrumentation((options) =>
                                {
                                    options.Propagator = new B3Propagator();
                                })
                                .AddProcessor(new MyActivityProcessor())
                                .AddZipkinExporter((o) =>
                                {
                                    o.ServiceName = "ServiceName";
                                    o.Endpoint = "http://zipkinendpoint:9411/api/v2/spans";
                                });
                        });
cijothomas commented 4 years ago

@christopher-taormina-zocdoc I think the issue is with the ordering. I will fix the ordering. Meanwhile - you can modify the Processor to check for customproperty in the OnEnd callback and it should work.

christopher-taormina-zocdoc commented 4 years ago

Yeah it seems to be fine with the OnEnd fight now so I can move forward with that.

cijothomas commented 4 years ago

Thanks for raising this. I will refactor the ActivitySourceAdapter so that the original examples would work as well. Adapter should expose GetSampling() method, Start() , Stop() method similar to actual ActivitySource. Instrumentation can call GetSampling() first and then call Start/Stop.

cijothomas commented 4 years ago

Thinking bit more on this - I think its safe to modify examples to expect the raw objects only in OnEnd callbacks.. ActivitySourceAdapter is invented to simulate the behavior of ActivitySource for old (DiagnosticSource based) instrumentations. In ActivitySource, there is no ability to start an activity with customProperties. ie there is no API like activitySource.StartActivity(...customProperty). So we don't need to provide this in ActivitySourceAdapter as well. The customProperty is added after Start. So the only place for user to access it is in the .OnEnd callback. (Will update examples to match this)

zfael commented 3 years ago

Hey guys! I've faced the same issue here and was not able to fix by using the @cijothomas suggestion, is there any other work-around avaialble?

christopher-taormina-zocdoc commented 3 years ago

@zfael I think things have changes in more recent versions of the dotnet sdk, where the source object is passed to an Enrich method rather than being placed on a custom property. Are you having issues with that newer code path?

zfael commented 3 years ago

@chris-smith-zocdoc thanks for the quick response, I think I'm using the most recent version of the SDK and I tried both

1) the example we find in the docs/same we find here in this issue 2) the approach using the Enrich method

both are not working at this point, or prolly me not doing the right thing.

services.AddOpenTelemetryTracing((builder) =>
            {
                builder
                .AddAspNetCoreInstrumentation()
                .AddHttpClientInstrumentation((options) => options.Enrich = (activity, eventName, rawObject) =>
                {
                    activity.SetTag("test", "test");
                    if (eventName.Equals("OnStartActivity"))
                    {
                        if (rawObject is HttpRequestMessage request)
                        {
                            activity.SetTag("requestVersion", request.Version);
                        }
                        else if (eventName.Equals("OnStopActivity"))
                        {
                            if (rawObject is HttpResponseMessage response)
                            {
                                activity.SetTag("responseVersion", response.Version);
                            }
                        }
                        else if (eventName.Equals("OnException"))
                        {
                            if (rawObject is Exception exception)
                            {
                                activity.SetTag("stackTrace", exception.StackTrace);
                            }
                        }
                    }
                })
                .AddProcessor(new EnrichingProcessor())
                .AddOtlpExporter(otlpOptions =>
                {
                    otlpOptions.Endpoint = "http://localhost:4000/";
                })
                .AddConsoleExporter();
          });

this is how my code is looking right now, as we can see, theres a activity.SetTag("test", "test"); on the Enrich method and thats not being triggered

any help would be much appreciated! 👍

zfael commented 3 years ago

wondering if the issue I just described on my first comment around AddHttpClientInstrumentation not calling the Enrich could be related to the issue https://github.com/open-telemetry/opentelemetry-dotnet/issues/1401 and its fix.

bringing this up since adding the same Enrich function in the AddAspNetCoreInstrumentation it triggers w/o issue so I was expecting the same behavior to happen on the AddHttpClientInstrumentation

for instance:

.AddAspNetCoreInstrumentation((options) => options.Enrich = async (activity, eventName, rawObject) =>
                {
                   ...
                })

Any idea/clue if that could be the case @cijothomas @christopher-taormina-zocdoc ?

christopher-taormina-zocdoc commented 3 years ago

@zfael I wasn't able to reproduce your issue with the latest rc. Can you add a breakpoint locally in the OnStartActivity method and see what's happening?

zfael commented 3 years ago

@christopher-taormina-zocdoc facing some issues right now to get a breakpoint in, kinda not being able to compile the whole project on my end so I can reference my project to use it as local libs.

Also, didn't find the .pdb files for OpenTelemetry packages so I could debug into it.

eddynaka commented 3 years ago

@zfael , our packages enable snupkg. If you configure your vs, it will find the reference...you can follow this reference: https://devblogs.microsoft.com/nuget/improved-package-debugging-experience-with-the-nuget-org-symbol-server/

zfael commented 3 years ago

@eddynaka thank you for the quick response on that, checking on it now!

zfael commented 3 years ago

OK cool -- thanks for that @eddynaka, I was able to hook into the AddAspNetCoreInstrumentation for instance but not for AddHttpClientInstrumentation, for some reason the .PDB for HTTP client instrumentation is still not being able to load.

I have been thinking and I'm running dotnet core so wondering if this AddHttpClientInstrumentation isn't compatible with it.

eddynaka commented 3 years ago

@zfael , in theory, they work the same way. another option is: download the opentelemetry-dotnet and manually add the csproj...

zfael commented 3 years ago

aight! I kinda feel that my issue is not totally related to this issue so I came up with this new issue/question where I've described the exact scenario I'm kinda facing right now.

thanks for the help on that tho, guys!