[AppInsights] Correlation with Application Insights Logging

[essmd]

The new WebJob SDK 2.1.0 supports logging using ApplicationInsights. I already tested it and it works really good. Since i have an abstraction for my message enqueuing, it was possible to get the RootId and ParentId (from Diagnostics Activity) and add those values to my QueueMessage payloads. Works like a charm!

Here i found the details about Diagnostics Activity correlation when enqueueing messages.

Now in my webjob project, i implemented a custom QueueProcessorFactory that returns a custom QueueProcessor. By overriding the method BeginProcessingMessageAsync it was also possible to deserialize the CloudQueueMessage payload and try to extract the RootId and ParentId (if available). I tried to get the Application Insights TelemetryClient and set the Operation.Id and Operation.ParentId accordingly but no effect.

My Question now is it possible to get the current execution telemetry somehow? As i remember, there is a extension method in the Web HttpContext.Current.GetRequestTelemetry() or something like that, to obtain the current request telemetry. I noticed in the ILogger implementation of the ApplicationInsights package, that the RequestTelemtry is stored somewhere in the ScopeProperties dictionary. That would be awesome, i dont know, how it otherwise would be possible to assign those two Operation Id's to correlate Enqueue with Dequeue and Execution/Trace logs.

See here for details about the RequestTelemetry in ILogger Scope Properties Dictionary.

When i click on "See all telemetry for this the root operation" of the POST/enqueue RequestTelemetry of the API, it ends with the DependencyTelemetry "Azure Queue" . It would be awesome if i could correlate also the job telemetry to this root operation like that:

API: RequestTelemetry: POST /enqueue API: DependencyTelemetry: Azure Queue JOB: RequestTelemetry: MyWebJobFunctionName JOB: TraceTelemetry: Started job execution JOB: .... JOB: TraceTelemetry: Completed job execution

[pragnagopa]

@brettsam - Do we have support for this?

[humbleice]

@essmd: You might be able to accomplish this correlation with the FunctionInvocationFilterAttribute. This attribute (similar to WebApi action filters) allows you to add logic before and after a job is processed. In this case you would use it to manage your own telemetry logging.

When the OnExecutingAsync method is invoked, you can create a new RequestTelemetry operation and store it until OnExecutedAsync is called, at which point you can dispose the operation.

In order to add correlation from the CloudQueueMessage you can check if FunctionExecutingContext.Arguments has a CloudQueueMessage instance. If it does you can try and grab the RootId and ParentId and use those values when creating the telemetry operation.

FunctionExecutingContext also provides a FunctionName and FunctionInstanceId which can be used to set the operation name and id.

When OnExecutedAsync is called you can use the FunctionExecutedContext.FunctionResult to set the Success status of the operation.

---

This approach essentially duplicates the request logging you would get from the built-in ILogger approach. I assume if both approaches are setup you would get two request telemetry items every time your job triggers.

[essmd]

Thanks for the detailed alterative way. Sounds a lot better and quite simpler than my way but also duplicates the telemetry for now. I think i will just be happy with the awesome ILogger and Application Insight support in webjobs for now, and wait+hope for a „public“/accessible property or way to acomplish that without duplicates.

Maybe it will be possible in future, its not a blocker for me but it would be so awesome and amazing - since the information should already be there. We will se :)

Thank you very much!

[MarkOtter]

For us, this indeed is a blocker. A solid fix would definitely be appreciated.

While the approach from @humbleice will probably work, I don't like the option of duplicating any logging code. I want to use as much of the existing package as possible.

So, taking your approach, but going a different route, I came up with this: (please feel free to comment)

1. In the OnExecutingAsync I try to take the OperationId delivered in the QueueMessage and store it, together with the FunctionInstanceId in some static concurrentdictionary which I've hidden inside a static class called OperationIdManager (bare with me here)

2. Taken the example for a custom TelemetryClientFactory I have overriden the CreateTelemetryChannel to just return the default (base) but wrapped by a class implementing the interface and forwarding all methods/properties

3. EXCEPT for the Send method in the wrapper. When it sees a Context.Operation.Id that matches a known FunctionInstanceId it modifies it by taking the mapped OperationId in the OperationIdManager. When the type of the ITelemetry item is RequestTelemetry, we know we are at the end of the request and so the mapping can be removed.

Some code:

public override Task OnExecutingAsync(FunctionExecutingContext executingContext, CancellationToken cancellationToken)  
{
   var queueMessage = executingContext.Arguments.Values.OfType<QueueMessage>().SingleOrDefault();
    if (queueMessage != null && queueMessage.OperationId != null)
    {
        OperationIdManager.RegisterOperationId(executingContext.FunctionInstanceId.ToString(), queueMessage.OperationId);
    }
    return base.OnExecutingAsync(executingContext, cancellationToken);
}

And

public void Send(ITelemetry item)
{
    var functionInstanceId = item.Context.Operation.Id;
    if (functionInstanceId != null)
    {
        var operationId = OperationIdManager.TryGetOperationId(functionInstanceId);
        if (operationId != null)
        {
            item.Context.Operation.Id = operationId;
            if (item is RequestTelemetry)
            {
                OperationIdManager.FreeOperationId(functionInstanceId);
            }
        }
    }
    _inner.Send(item);
}

(@essmd)