Worker scopes

worker_scopes.md

Current template

protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
    while (!stoppingToken.IsCancellationRequested)
    {
        _logger.LogInformation("Worker start loop at: {time}", DateTimeOffset.Now);
        await httpClient.GetAsync("http://microsoft.com", stoppingToken);
        _logger.LogInformation("Worker end loop at: {time}", DateTimeOffset.Now);
    }
}

Logs are not correlated with or without app insights.

info: WorkerWithScopes.Worker[0]
      Worker end loop at: 07/19/2019 11:23:49 -07:00
info: WorkerWithScopes.Worker[0]
      Worker start loop at: 07/19/2019 11:23:49 -07:00

Add scope

WorkerScope works on top of System.Diagnostics.Activity and can work along with HttpClient and Azure SDKs.

protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
    while (!stoppingToken.IsCancellationRequested)
    {
        using var scope = _logger.BeginWorkerScope();
        _logger.LogInformation("Worker start loop at: {time}", DateTimeOffset.Now);
        await httpClient.GetAsync("http://microsoft.com", stoppingToken);
        _logger.LogInformation("Worker end loop at: {time}", DateTimeOffset.Now);
    }
}

or

protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
    while (!stoppingToken.IsCancellationRequested)
    {
        var message = (await _serviceBusReceiver.ReceiveAsync(1)).Single();
        using var scope = _logger.BeginWorkerScope(message.ExtractActivity());
        
        _logger.LogInformation("Worker start loop at: {time}", DateTimeOffset.Now);
        await httpClient.GetAsync("http://microsoft.com", stoppingToken);
        _logger.LogInformation("Worker end loop at: {time}", DateTimeOffset.Now);
    }
}

Providers can correlate logs

info: WorkerWithScopes.Worker[0]
      => SpanId:9d2f81c429565d48, TraceId:50baf6cd0b6697439cf60104e0315515, ParentId:
      Worker start loop at: 07/18/2019 20:22:08 -07:00
info: WorkerWithScopes.Worker[0]
      => SpanId:9d2f81c429565d48, TraceId:50baf6cd0b6697439cf60104e0315515, ParentId:
      Worker end loop at: 07/18/2019 20:22:08 -07:00

Context is propagated into outgoing http requests (even without AppInsights)

AppInsights shows full transaction

WorkerScope.cs

using System;
using System.Diagnostics;
using Microsoft.Extensions.Logging;

namespace Microsoft.Extensions.Hosting
{
    public static class LoggerExtensions
    {
        public static IDisposable BeginWorkerScope(this ILogger logger)
        {
            return logger.BeginScope(new WorkerScope());
        }

        public static IDisposable BeginWorkerScope(this ILogger logger, Activity activity)
        {
            return logger.BeginScope(new WorkerScope(activity));
        }

        public class WorkerScope : IDisposable
        {
            public Activity Activity { get; }

            public WorkerScope(Activity activity)
            {
                this.Activity = activity;
                if (this.Activity.StartTimeUtc == default)
                {
                    this.Activity.SetIdFormat(ActivityIdFormat.W3C);
                    this.Activity.Start();
                }
            }

            public WorkerScope() : this(new Activity("foo"))
            {
            }

            public override string ToString()
            {
                return string.Format("SpanId:{0}, TraceId:{1}, ParentId:{2}",
                    this.Activity.IdFormat == ActivityIdFormat.W3C ? this.Activity.SpanId.ToHexString() : this.Activity.Id,
                    this.Activity.IdFormat == ActivityIdFormat.W3C ? this.Activity.TraceId.ToHexString() : this.Activity.RootId,
                    this.Activity.IdFormat == ActivityIdFormat.W3C ? this.Activity.ParentSpanId.ToHexString() : this.Activity.ParentId);
            }

            public void Dispose()
            {
                this.Activity.Stop();
            }
        }
    }
}

z_app_insights_tracing.png

z_no_app_insights_out_http.png