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)

 

Imperative bindings in Azure Functions

In-built bindings provided by Azure Functions for most cases are more than sufficient - you don't have to manage and configure them on your own, all you're supposed to do is to focus on business logic and your codebase. There's a gap however when using bindings from a function.json file - what if I have to create a binding at runtime? Fortunately even this case is covered and you can easily build bindings, even using data delivered in your HTTP request.

Use case

Let's say you'd like to create a function, which fetches data from a CosmosDB instance. The issue here is, that you want to query a particular collection of documents. Normally you'd use following binding:

/
{
  "name": "inputDocument",
  "type": "documentDB",
  "databaseName": "MyDatabase",
  "collectionName": "{collectionId}",
  "connection": "MyAccount_COSMOSDB",     
  "direction": "in"
}

but there's no way to dynamically replace {collectionId} using data from a HTTP request(it works for other triggers like queue for the sqlQuery parameter however). We need to find another way of doing this avoiding building our own repositories and services, which would obscure the whole function.

If you read documentation carefully(especially C# reference), you'll find, that there's a possibility to use dynamic bindings via imperative bindings. The example of usage could like this:

/
using (var output = await binder.BindAsync<T>(new BindingTypeAttribute(...)))
{
    ...
}

With such feature we can implement our dynamic CosmosDB collection binding.

Implementing imperative binding in your function

I'll show you an example of using CosmosDB imperative binding in a CSX file, but the same rules apply to regular C# files. The first thing we need here is to reference a binding attribute. In our case it will be DocumentDBAttribute from Microsoft.Azure.WebJobs.Extensions

/
#r "Microsoft.Azure.WebJobs.Extensions.DocumentDB"

Then we have to update function's signature so it accepts Binder type:

/
public static async Task<HttpResponseMessage> Run(HttpRequestMessage req, Binder binder, TraceWriter log)

Now we can use imperative binding e.g. to load a collection dynamically:

/
var collection = await binder.BindAsync<IEnumerable<dynamic>>(
        new DocumentDBAttribute("foo", "{dynamic_parameter}"));

The whole function could look like this(don't pay attention to all those dynamics, normally I'd use slightly other structures and methods):

/
#r "Microsoft.Azure.WebJobs.Extensions.DocumentDB"

using System.Net;

public static async Task<HttpResponseMessage> Run(HttpRequestMessage req, Binder binder, TraceWriter log)
{
	dynamic data = await req.Content.ReadAsAsync<object>();
	using(var collection = await binder.BindAsync<IEnumerable<dynamic>>(
			new DocumentDBAttribute("foo", data.collectionId.Value.ToString()))) 
	{
		var firstDocumentId = collection.First().id.Value.ToString();
		return req.CreateResponse(HttpStatusCode.OK, new {id = firstDocumentId});
	}
}

When I called my function using a following payload:

/
{
    "collectionId": "bar"
}

I'll get following result:

/
{"id":"I am FOO!"}

Summary

This was just a simple example of how you can extend your functions using imperative bindings. The best things is that is allows you to avoid implementing typical patterns usable in traditional web applications and keeps functions relatively clean. Feel free to experiment with those - using dynamic bindings is a really powerful feature and for sure will make your function even more powerful.