Tuesday, October 22, 2019

Tuesday Quickie: ILogger in Azure Functions done right

So we had a discussion at work yesterday about how to use ILogger from Microsoft.Extensions.Logging in our Azure Functions v2 projects.

All the samples have a hang-over from the v1 days where the function method takes an ILogger as a method dependency. I asserted that a cleaner way would be to have ILogger as a class-level dependency, injected via the constructor.

The only problem was that it didn't work - the MSDI wasn't resolving ILogger when constructing our functions class.

namespace MyFunctionApp
{
    public class MyFunctionClass
    {
        private readonly ILogger logger;

        // DOESN'T WORK!
        public MyFunctionClass(ILogger logger)
        {
              this.logger = logger;
        }

        [FunctionName("MyFunctionName")]
        public async Task<IActionResult> MyFunctionMethod(
            [HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)]
            HttpRequest req,
            ILogger log) // WORKS!
       {
           ...
       }
    }
}

A bit of a proof-of-concept later and I found the trick - use ILogger<T> as the constructor dependency - where T is the class that owns the method.!

    public class MyFunctionClass
    {
        private readonly ILogger logger;

        // WORKS!
        public MyFunctionClass(ILogger<MyFunctionClass> logger)
        {
              this.logger = logger;
        }
        ...
    }

But why? 

What's going on is that the Azure Functions v2 runtime sets up the DI to serve an ILogger when method-injection is used, but not for constructor injection. For constructor injection the runtime has set the DI to serve up only ILogger<T>.

Looking at the differences between the loggers that the two DI methods return, we can actually make sense of why the behaviours are different.

The ILogger returned for method injection is configured with the category "Function.MyFunctionName.User".

The ILogger<T> returned for constructor injection, however, gets a category of "MyFunctionApp.MyFunctionClass" instead. 

The Azure Functions v2 runtime is building a logger based on the FunctionName attribute for method injection - it's a special case hangover from v1!

So to get hold of an ILogger in your function class using constructor injection, you just need to ask for an ILogger<MyClass> instead! 

Seemples!

Update - 2019-11-05:

So I missed out a rather important part of this post... the pattern above is lovely, but it doesn't work

None of the logging to ILogger<MyClass> instances appear in Application Insights - but logging from the Azure Functions v2 runtime itself does.

Actually the problem isn't the pattern above at all, but another nasty little Azure Functions v1 hangover that Microsoft hasn't fixed yet.

By default, the Azure Functions v2 runtime filters out any logging that's not from the runtime itself, or from ILogger instances that the runtime provides (with the "Function.MyFunctionName.User" style category).

The fix is easy - but irritating. Add logging configuration to your
host.json file, thus:


{
  "version": "2.0",
  "logging": {
 "logLevel": {
   "MyFunctionApp": "Trace"
 }
  }
}
There's an issue that was openned on GitHub in April 2019 about this ( https://github.com/Azure/azure-functions-host/issues/4345 ), so I assume Microsoft will get around to removing the filtering at some point.