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)

 

Digging deeper again - querying Application Insights data

In the one of the previous post I presented you the basics of using Analytics in Application Insights. Just to remind you - it's a tool, which allows you to get much more detailed information regarding how your application perform and behaves. In this post I'll try to encourage you to use this tool on daily basis, especially when something is clearly wrong and you don't want to click through all those tabs in Azure Portal.

Quickly finding an exception

Let's consider following example - you're informed by your client, that he or she got an error saying Object reference not set to an instance of an object. You know the time and assume, that we're facing NullReferenceException here. What could you do to quickly find more details regarding this exception? Let's consider following query:

/
exceptions
    | where timestamp >= ago(24h) 
        and type == "System.NullReferenceException" 
        and outerAssembly 
            contains "MyProject" 
    | project method, details, timestamp 

This query will project a simple result containing a method in which an exception was thrown, details(like inner stack) and the exact time when it occurred. You can modify it and use different timestamp to get results, which will satisfy you the most.

Finding pages which are loading too slow

This is another example - you have a SPA and you'd like to know, which pages are loading longer, that a fixed threshold. Fortunately we can use a really simple query, which can help us here:

/
pageViews
    | where duration > 500

Yes, this is really it. Of course you can extend this query and use other metrics to further filter the data like:

/
pageViews
    | where duration > 50
        and operation_Name == "some_operation"
        and timestamp > ago(1h)  

Or even visualize your data to be aware which slower requests are really the slowest ones:

/
pageViews
    | where duration >= 250
    | render piechart  

Custom metrics

You can use predefined metrics to gather some information about your application, but where this tool really shines is the possibility to query custom metric. This allows you to easily build your own reports and really focus on what you're interested in.

For example I'd like to know how many times given method is called so I can be aware of all potential hot-paths and focus my optimization efforts on it. To do this I need two things:

  • a tool, which will decorate methods calls with a custom metrics logging(AOP/assembly weaving will help here)
  • custom query in Application Insights Analytics

Let's say, that this decorator will log one thing - a method name. Now in Analytics we could create a query, which would use this custom metric to show us which method is called the most.