Fixing ILogger usage in Azure Functions with Application Insights

If you go here you'll get some information regarding integrating Application Insights with

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)

 

Add comment