Azure-webjobs-sdk: Create telemetry properties inside a IServiceScope

[sebastieno]

I have a WebJob running an infinite loop. For each iteration of this loop, I want to log some informations (traces, exceptions and one request) to AppInsights. And I need that each of those informations, for a same iteration loop, share the same correlationId (to be able to group all logs in the azure portal).

Here the code I use to declare AppInsights :

this.hostBuilder = new HostBuilder()
    .ConfigureLogging((context, builder) =>
    {
        builder.AddConfiguration(context.Configuration.GetSection("Logging"))
            AddApplicationInsights(options => options.InstrumentationKey = context.Configuration["ApplicationInsightsInstrumentationKey"]);
    });

Then I have a hosted service which run multiples tasks, and an infinite loop in each task :

internal class MyHostedService : IHostedService
{
    public Task StartAsync(CancellationToken cancellationToken)
    {
        this.taskCancellationToken = new CancellationTokenSource();

        foreach (var xxx in yyy)
        {
            this.tasks.Add(Task.Run(async () =>
            {
                while (!this.taskCancellationToken.IsCancellationRequested)
                {
                    using (var scope = this.serviceScopeFactory.CreateScope())
                    {
                        [...]
                    }
                }
            }
        }
    }
}

So each iteration has its own scope.

Then, to be able to log a request, I create an operation based on the TelemetryClient:

using(var operationHolder = this.telemetryClient.StartOperation<RequestTelemetry>("myoperation"))
{
    try
    {
        [...]

        operationHolder.Telemetry.Success = true;
    }
    catch(Exception e)
    {
        operationHolder.Telemetry.Success = false;
    }
}

And I also add some logs:

var logger = scope.ServiceProvider.GetRequiredService<ILogger<MyHostedService>>();
logger.LogInformation("Process ended successfully");

I want that both my logger and operationHolder share the same properties (mainly the correlationId which is a Guid).

My operationHolder properties are initialized in that way and it's working correctly :

operationHolder.Telemetry.Properties["correlationId"] = correlationId.ToString();

The ApplicationInsightsLogger, which is used when I call logger.LogInformation, creates a TraceTelemetry which use the TelemetryClient (but not the same telemetry as the operationholder) to get properties to add to AppInsights. My problem here is that the TelemetryClient is declared as Singleton. So I can declare GlobalProperties but not Properties specific to each iteration of my loop.

My only workaround is to create LoggerScope and add my properties in the state :

var loggerScope = logger.BeginScope(new Dictionary<string, object>
{
    ["correlationId"] = correlationId
});

The only problem here is that my correlationId appears as prop___correlationId, I think to avoid collision between state and telemetry properties.

Expected behavior

Be able to declare scoped properties inside a TelemetryClient.

Actual behavior

TelemetryClient is a Singleton so I can't declare properties for a scope.

Known workarounds

As exposed previously, use a BeginScope in addition of StartOperation.

Related information

Provide any related information

• Microsoft.Azure.WebJobs.Logging.ApplicationInsights : 3.0.6
• Microsoft.Azure.WebJobs.Extensions : 3.0.2

[dcarr42]

Research ITelemetryInitializer
https://github.com/Microsoft/ApplicationInsights-aspnetcore/wiki/Custom-Configuration#add-request-level-properties-for-all-telemetry-items

I'm not sure if it works with logger scopes I thinking maybe there's a chance. The example shows a per request example when resolving from the DI container.

[sebastieno]

I already tried to use a ITelemetryInitializer which use the ServiceProvider :

public class OperatorExecutionContextTelemetryInitializer : ITelemetryInitializer
{
    private readonly IServiceProvider serviceProvider;

    public OperatorExecutionContextTelemetryInitializer(IServiceProvider serviceProvider)
    {
        this.serviceProvider = serviceProvider;
    }

    public void Initialize(ITelemetry telemetry)
    {
        var operatorExecutionContext = this.serviceProvider.GetService<OperatorExecutionContext>();
        if (operatorExecutionContext != null && telemetry is OperationTelemetry operationTelemetry)
        {
            operationTelemetry.Properties["correlationId"] = operatorExecutionContext.CorrelationId.ToString();
        }
    }
}

It's not working because my Initializer is not created when I create my new Scope, so the IServiceProvider instance is not shared between my loop iteration and the initializer.

[dcarr42]

At some point is was changed to Singleton. Maybe by taking control of the lifetime of the TelemetryClient instead of using the extensions. It might require some hackery.

[sebastieno]

Yes I saw this change.
As you said, set the TelemetryClient as Scoped should help me to solve my problem but I prefer to avoid hackery if possible.

[dcarr42]

Hopefully it is not illegal to new up TelemetryClient and register it with the container. 😉

[sebastieno]

I tried to add the TelemetryClient as Scoped :

services.AddScoped<TelemetryClient>(provider =>
{
    TelemetryConfiguration configuration = provider.GetService<TelemetryConfiguration>();
    TelemetryClient client = new TelemetryClient(configuration);

    ISdkVersionProvider versionProvider = provider.GetService<ISdkVersionProvider>();
    client.Context.GetInternalContext().SdkVersion = versionProvider?.GetSdkVersion();

    return client;
});

But same behavior, it looks like the TelemetryClient is not resolved for each scoped (maybe an internal reference somewhere).

I would like to avoid as much as possible to make some hackery because of two things : be able to update my nugets version without to have to rewrite all my code, and do not create potential performance issues (I have others webjobs when I need to handle a lot of messages per seconds).

I was thinking that my need (be able to add telemetry properties inside a IServiceScope) was a common things. It's working correctly for ASPNET Core (because of HttpContextAccessor) but not in a WebJob context.

[dcarr42]

Agreed. I would not mix logging and telemetry client and just expect them to work. But there is possibly a gap to fill here.

I would stick to using AppInsights logger but inject into the IHostedService and use the inbuilt scopes

  using (var scope = _logger.BeginScope("Begin operation"))
  {
      _logger.LogInformation("Test");
  }

[sebastieno]

In fact, the ApplicationInsightsLogger creates a tracetelemetry and calls tracktrace from TelemetryClient. So you can mix logging with telemetry informations. The only problem is that the TelemetryClient used is the singleton one, so it cannot contain scoped properties.

[dcarr42]

True enough...But if you can support IReadOnlyCollection<KeyValuePair<string, object>> for your scope why bother as it will get appended to the telemetry. The ILogger abstraction is exactly that.

[sebastieno]

Using state params within the logger.BeginScope is almost perfect. The only problem is that all my properties are prefixed by prop__. So all my requests have a property named correlationId and all my traces have a property named prop__correlationId.

It's enough for me now but it seems weird to not being able to have scoped properties within the telemetryclient (maybe a regression since the change of Scope to Singleton).

[dcarr42]

Nice one..I will not harp on about it but I still think using RequestTelemetry inside the IHostedService is a _little bit_ of a misuse. But I totally see your predicament. :-)

[brettsam]

Ultimately -- you want that correllationId to be attached to all telemetry inside that operation, but without the prop__ prefix?

One thing you may be able to do is take advantage of Activity and use an ITelemetryInitializer to stick your correllation id onto your telemetry.

If I'm undnerstanding your scenario correctly, I wrote an IHostedService like this:

internal class MyHostedService : IHostedService
{
    private readonly TelemetryClient _client;
    private readonly IServiceScopeFactory _serviceScopeFactory;
    private readonly CancellationTokenSource _cts = new CancellationTokenSource();

    public MyHostedService(IServiceScopeFactory serviceScopeFactory, TelemetryClient client)
    {
        _serviceScopeFactory = serviceScopeFactory;
        _client = client;
    }

    public Task StartAsync(CancellationToken cancellationToken)
    {
        Task.Run(async () =>
        {
            while (!_cts.IsCancellationRequested)
            {
                using (var scope = _serviceScopeFactory.CreateScope())
                {
                    using (var operationHolder = _client.StartOperation<RequestTelemetry>("myoperation"))
                    {
                        Guid correllationId = Guid.NewGuid();
                        Activity.Current.AddTag(nameof(correllationId), correllationId.ToString());

                        var logger = scope.ServiceProvider.GetService<ILogger<MyHostedService>>();
                        logger.LogInformation("Something!");

                        operationHolder.Telemetry.Success = true;
                    }
                }

                await Task.Delay(2000, _cts.Token);
            }
        }, _cts.Token);

        return Task.CompletedTask;
    }

    public Task StopAsync(CancellationToken cancellationToken)
    {
        _cts.Cancel();
        return Task.CompletedTask;
    }
}

Notice the Activity.Current line.

Then you can write an ITelemetryInitializer that looks at Activity.Current, pulls out the relevant details, and applies them directly to the telemetry however you want.

[sebastieno]

I read some code from the TelemetryClient and indeed it seems to be a good solution using the Activity.Current and a custom ITelemetryInitializer.

I made some quick tests and it looks good. I will try to make some deeper tests and I keep you in touch.

Thanks a lot.