Accessing an orchestration history in Durable Functions

One of the important aspects of Durable Functions is the fact, that you're able to access each orchestration history, inpect and analyze it when you need to do so. This is a great addition to the whole framework since you're able to both:

  • leverage current features like Application Insights integration
  • write a custom solution, which will extend current capabilities and easily integrate with your systems

However what are the options, which we're given? Let's take a look!

Application Insights

There's an extensive guide available here, which explains in details how one can access and use Application Insights integration and query the data. There's one important information listed there:

By default, Application Insights telemetry is sampled by the Azure Functions runtime to avoid emitting data too frequently. 
This can cause tracking information to be lost when many lifecycle events occur in a short period of time. 

So it's important to be aware of this flaw and always design your solution so it's don't rely on possibly lost information.

Another important thing is the configuration:

/
{
    "logger": {
        "categoryFilter": {
            "categoryLevels": {
                "Host.Triggers.DurableTask": "Information"
            }
        }
    }
}

Sometimes it's imporant to adjust logging levels since in Functions there's many events that are being constantly logged - if you're using Azure subscription with limits(like MSDN subscriptions) you can easily run out of free quota, what will prevent your functions from logging.

Storage

This is nothing surprising that Durable Functions also use Storage Account to store data. You can get the same results as accessing AI by going to the Storage Account attached to the Function App instance and accessing history table. Its name is listed in host.json:

/
{
  "durableTask": {
    "HubName": "SampleHubVS"
  }
}

So when you access your Storage Account, it should be there:

Fixing ILogger usage in Azure Functions with Application Insights

NOTE: This issue is reported and discussed by me here and it's quite possible a fix will be available soon. Stay tuned!

If you go here you'll get some information regarding integrating Application Insights with Azure Functions. Most are pretty basic stuff, however there's ILogger interface mentioned, which is supposed to give you more information(or at least this is what the documentation says, in fact the advantage comes from structured logging). Consider following method signature:

/
/// <summary>Writes a log entry.</summary>
/// <param name="logLevel">Entry will be written on this level.</param>
/// <param name="eventId">Id of the event.</param>
/// <param name="state">The entry to be written. Can be also an object.</param>
/// <param name="exception">The exception related to this entry.</param>
/// <param name="formatter">Function to create a <c>string</c> message of the <paramref name="state" /> and <paramref name="exception" />.</param>
void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter);

Wow, this is so cool - I have one method in which I can pass all what I need(and pass formatter, which will take care of formatting a message to be logged). There's one thing - actually it doesn't work. In this blog post I'll show you how you can fix this(and possibly encourage you to read codebases of products and libraries you use on daily basis).

Track it!

I found this issue while playing with Ilogger interface a bit. I created following function:

/
using System.Net;

public static async Task<HttpResponseMessage> Run(HttpRequestMessage req, ILogger log)
{
    var state = new State { TimeStamp = DateTime.Now };

    log.LogCritical("This is critical information!!!");
    log.LogDebug("This is debug information!!!");
    log.LogError("This is error information!!!");
    log.LogInformation("This is information!!!");
    log.LogTrace("This is trace information!!!");
    log.LogWarning("This is warning information!!!");
    log.Log(LogLevel.Trace, 0, state, null, (s, ex) => {
        return $"Action happened at {s.TimeStamp} with ID {s.Id}";
    });

    return req.CreateResponse(HttpStatusCode.OK, "Hello!");
}

public class State {
    public string Id => Guid.NewGuid().ToString();
    public DateTime TimeStamp {get; set;}
}

I expected, that in the Logs window I'll see a message for each method called. This is the output I got:

/
2017-06-27T09:15:39.310 Compilation succeeded.
2017-06-27T09:15:39.341 This is critical information!!!
2017-06-27T09:15:39.341 This is debug information!!!
2017-06-27T09:15:39.341 This is error information!!!
2017-06-27T09:15:39.341 This is information!!!
2017-06-27T09:15:39.341 This is trace information!!!
2017-06-27T09:15:39.341 This is warning information!!!
2017-06-27T09:15:39.341 Function completed (Success, Id=3a8d3a42-b9ba-4dcf-9f75-02c01883ca8f, Duration=565ms)

Hmmm - I don't see my Action happened at {s.TimeStamp} with ID {s.Id} message here. Checking it in the portal also failed - there was clearly something wrong with this method. What is more - using extension method worked though they also call Log method from ILogger. Let's check LogInformation method:

/
public static void LogInformation(this ILogger logger, EventId eventId, Exception exception, string message, params object[] args)
{
  if (logger == null)
	throw new ArgumentNullException("logger");
  logger.Log<object>(LogLevel.Information, eventId, (object) new FormattedLogValues(message, args), exception, LoggerExtensions._messageFormatter);
}

Nothing fancy here. The only thing which I found suspicious was FormattedLogValues class. If you check it, you'll see that it implements a couple of interfaces - IReadOnlyList<KeyValuePair<string, object>>, IReadOnlyCollection<KeyValuePair<string, object>>, IEnumerable<KeyValuePair<string, object>>, IEnumerable. OK - how is it connected to the main issue? Let's go deeper!

Going deeper

I decided to check how ApplicationInsightsLogger class is implemented. Here's its source code:

/
public void Log<TState>(Microsoft.Extensions.Logging.LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
  if (!this.IsEnabled(logLevel))
	return;
  string formattedMessage = formatter != null ? formatter(state, exception) : (string) null;
  IEnumerable<KeyValuePair<string, object>> values = (object) state as IEnumerable<KeyValuePair<string, object>>;
  if (values == null)
	return;
  if (this._categoryName == "Host.Results")
	this.LogFunctionResult(values, exception);
  else if (this._categoryName == "Host.Aggregator")
	this.LogFunctionResultAggregate(values);
  else if (exception != null)
	this.LogException(logLevel, values, exception, formattedMessage);
  else
	this.LogTrace(logLevel, values, formattedMessage);
}

Wait a second - we're casting TState to IEnumerable<KeyValuePair<string, object>> and if this fails, we are logging... nothing?! This is more than just unexpected.

Solution

Actually the easiest and the dirtiest solution is to pass TState parameter as IEnumerable<KeyValuePair<string, object>> like this:

/
using System.Net;

public static async Task<HttpResponseMessage> Run(HttpRequestMessage req, ILogger log)
{
    var state = new List<KeyValuePair<string, object>>() { new KeyValuePair<string, object>("data", new State { TimeStamp = DateTime.Now }) };

    log.LogCritical("This is critical information!!!");
    log.LogDebug("This is debug information!!!");
    log.LogError("This is error information!!!");
    log.LogInformation("This is information!!!");
    log.LogTrace("This is trace information!!!");
    log.LogWarning("This is warning information!!!");
    log.Log(LogLevel.Trace, 0, state, null, (s, ex) => {
        return $"Action happened at {((State)s[0].Value).TimeStamp} with ID {((State)s[0].Value).Id}";
    });

    return req.CreateResponse(HttpStatusCode.OK, "Hello!");
}

public class State {
    public string Id => Guid.NewGuid().ToString();
    public DateTime TimeStamp {get; set;}
}

or implemented similar to FormattedLogValues class. Once I fixed the type of my parameter passed, my function returned expected messages:

/
2017-06-27T09:26:36.428 Compilation succeeded.
2017-06-27T09:26:36.601 Function started (Id=7d7f722e-5687-438f-9e46-4989619cc0a5)
2017-06-27T09:26:37.164 This is critical information!!!
2017-06-27T09:26:37.164 This is debug information!!!
2017-06-27T09:26:37.164 This is error information!!!
2017-06-27T09:26:37.164 This is information!!!
2017-06-27T09:26:37.164 This is trace information!!!
2017-06-27T09:26:37.164 This is warning information!!!
2017-06-27T09:26:37.176 Action happened at 6/27/2017 9:26:37 AM with ID 7dfc65cd-2418-4eb1-95c9-fdd6637dfec6
2017-06-27T09:26:37.176 Function completed (Success, Id=7d7f722e-5687-438f-9e46-4989619cc0a5, Duration=574ms)