Monitoring your Function App with ease

This post was created thanks to great support from people directly involved in Azure Functions in Microsoft - Donna Malayeri and Paul Batum

Introduction

Azure Functions make developing small services easier, especially with all those triggers and bindings, which allow you to skip writing boilerplate code and focus directly on your business needs. They are also provided with a possibility to "pay-as-you-go" with Consumption Plan supported. Currently many people take advantage of this feature and try to make the most of it by not exceeding a monthly free cap of executions and execution time. What if you'd like to monitor somehow how many times you function's been executed? Fortunately there're two ways of doing it and both are a piece of cake.

A graph presenting executions of a function triggered once per 5 minutes

Using Azure Portal

The easiest way to monitor your Function App(unfortunately you cannot monitor each function separately, at least not now) is to go to portal and check metrics of an App service plan, which is used to host it(to be more specific - its metrics). To do so I'll quote Paul directly here:

/
> There appears to be a bug that is making this harder than it should be. Try the following steps...
> Open Function App. Platform Features -> All Settings -> Click on Function Execution Count graph -> uncheck count, check units.

By doing those steps, you should be able to see a chart with a metric selected:

Weekly metrics of my function

There's one gotcha here however:

/
> Function Execution units are in mbmilliseconds, you'll need to divide by 1024000 to get gbsec.

One more thing - there's now way to know what's the aggregated value e.g. from a month - for now you have to do it on your own.

Using API

There's one more way to check the metrics - using a REST API of Azure Monitoring. This method is described on StackOverflow also by Paul and with a direct reference to walkthrough of Azure Monitoring REST API. The main idea is to call API, which will return to you something similar to following:

/
{
  "value": [
    {
      "data": [
        {
          "timeStamp": "2016-12-10T00:00:00Z",
          "total": 0
        },
        {
          "timeStamp": "2016-12-10T00:01:00Z",
          "total": 140544
        },
        {
          "timeStamp": "2016-12-10T00:02:00Z",
          "total": 0
        },
        {
          "timeStamp": "2016-12-10T00:03:00Z",
          "total": 0
        },
        {
          "timeStamp": "2016-12-10T00:04:00Z",
          "total": 0
        }
      ],      
      "name": {
        "value": "FunctionExecutionUnits",
        "localizedValue": "Function Execution Units"
      },
      "type": "Microsoft.Insights/metrics",
      "unit": "0"
    }
  ]
}

Once you have the result, it's easy to write a custom tool, which will calculate all metrics and give you an insight into your's functions performance.

 

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)