Google-cloud-dotnet: Google.Cloud.Diagnostics does not seem to be working with BackgroundService

[mahesh-bennie]

Environment details

• OS: Windows 10
• .NET version: .net core 3.1
• Package name and version: Google.Cloud.Diagnostics.AspNetCore v4.0.0

Problem Description

Been trying to get tracing information over to GCP by following this documentation (http://googleapis.github.io/google-cloud-dotnet/docs/Google.Cloud.Diagnostics.AspNetCore/)

I've noticed that none of the tracing information (nor metrics and error logs) flow through to GCP when execution occurs in a background service (as implemented following this example https://docs.microsoft.com/en-us/aspnet/core/fundamentals/host/hosted-services?view=aspnetcore-3.1&tabs=visual-studio#queued-background-tasks). I did however, notice that everything shows up if I don't use background service (aka just hitting the method directly from the controller instead of queuing it up).

Is this a known issue? Is there something I need to pass along to the background service in order to get information flowing? This is a snippet of how I establish tracing (I'm just trying to obtain tracing anytime we perform http requests on our httpclient)

public class TraceHandler : DelegatingHandler
    {
        private IManagedTracer _tracer;

        public TraceHandler(IManagedTracer tracer)
        {
            _tracer = tracer;
        }

        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
            using (_tracer.StartSpan($"{request.RequestUri}"))
            {
                var response = await base.SendAsync(request, cancellationToken);
                return response;
            }
        }
    }

This is what is currently happening in my endpoint (which doesn't work):

[HttpGet("[controller]/[action]")]
        public IActionResult AddToQueue()
        {
            if (!_cancellationToken.IsCancellationRequested)
            {
                Task.Run(() => QueueWork());
            }

            return Accepted();
        }

QueueWork does the following:

private void QueueWork()
        {
            _taskQueue.QueueBackgroundWorkItem(async token => await _example.PerformWork());
        }

_taskQueue.QueueBackgroundWorkItem is basically a copy of the implementation in the article described above.

Now if the controller were to call _example.PerformWork directly, then I do see trace logs on GCP.

[amanda-tarafa]

I'm looking into this. Will get back when I know more.

[amanda-tarafa]

In your first post:

Environment details
OS: Windows 10
.NET version: .net core 3.1
Package name and version: Google.Cloud.Diagnostics 4.0.0

Can I confirm that the package you are using is Google.Cloud.Diagnostics.AspNetCore 4.0.0?

[mahesh-bennie]

Ah yes. I'll update the post. Sorry about that.

[amanda-tarafa]

@mahesh-bennie What you are seeing is not an issue with the Diagnostics library, it's just working as intended.
All the setup described here is for tracing to happen automatically within a request. And that is working as expected when you call PerformWork directly from your controller instead of queueing it. For that to happen we rely on the ASP.NET Core pipeline to execute, in particular our own custom middleware.
The BackgroundService executes outside of requests (that is actually its sole purpose), and not as part of the ASP.NET Core pipeline, so our custom middleware is not involved and trace is not fully setup for the BackgroundService.
The good news is that you only need a couple lines of code to set it up yourself on your BackgroundService (luckily ASP.NET Core Dependecy Injection does work for BackgroundService and you can reuse some of the setup).

Attached you'll find a working example. My controller has two actions, GetInmediate (calls DoWork) and GetDeffered (enqueus DoWork). I skipped the DelegatingHandler bit for the example, I'm simply starting the trace on the actions, one or the other approach won't make a difference. And DoWork does receive a tracer, to make sure that it uses the correct one whether is called from within a request or from within the BackgroundService.
The BackgroundService implementation is copied from the MS tutorial you linked, I removed the logger bit to make the code simpler (this is just for demonstration anyways) and I added the two lines of code that you'll be interested in, in QueuedHostedService.
You'll have to change the PROJECT-ID placeholder on Startup.cs to get this working.

Note that for GetInmediate you'll get one trace containing 2 spans, one for the request and one for DoWork. For GetDeffered you'll get two traces with one span each, one trace for the request and one trace for DoWork. This is as expected and there is no way around it by definition. When DoWork is executed by the background service, the GetDeffered request ended "a long time ago" and the request trace with it.

Let me know if this answers your question.
BackgroundServiceLogging3.1.zip

[amanda-tarafa]

@mahesh-bennie Any luck trying my code? Any remaining related questions?

[mahesh-bennie]

@amanda-tarafa Hey thanks for responding and providing a great solution! I'm going to try it out now and will let you know of the results.

[mahesh-bennie]

@amanda-tarafa It worked fantastically! I can see all the traces flowing through. I guess the TraceHeaderContext.Create was the piece I was missing.

In order to get my delegate handler to work with the trace, all I needed to do was invoke ContextTracerManager.GetCurrentTracer() and it just worked!

Thanks again so much for not just stopping with "oh that's how its designed" but with an actual working example!