Add support for injecting the Function provided ILogger into own DI Framework

[vsadams]

In my scenario, I have made a custom binding that allows me to inject objects into my functions via my own IOC container. Before the latest update to the V2 function runtime (2.0.11587-alpha to 2.0.11651-alpha), I was able to borrow the ILogger from the ExtensionConfigContext's LoggerFactory. I just provided the IOC a ref back to the factory then whenever I needed a logger, I just asked it for one.

The latest update seems to have broken this. I still get a logger from the factory however, none of the loggers log....which is a bummer. I have sorta worked around this by just bringing my own LoggerFactory to the table.

However, I would rather go back to my Sidecar pattern approach and use the provided factory. The benefit of using the provided one is I can retrieve a lot of context in my logs that I would otherwise not be able to retrieve, like function name, instanceid, etc. I am sure there might be other ways around this, which I am open to hearing.

[paulbatum]

@brettsam can you help out with this one?

[brettsam]

There's some major refactoring going on around our internal DI in V2, which may address the issue. But I will leave this open to make sure we take it into account.

@fabiocav FYI

[isaacrlevin]

@brettsam @fabiocav is there an update on this? I have a sample of the following scenarios that does not work

• .NET Standard 2 CL that has a service
• I want to share this service between a v2 function and an ASP.NET Core App
• The service has a dependency on ILogger
• ASP.NET Core leverages ILogger for DI purposes, but Azure Functions does not
• I can either use generic ILogger as dependency in service but that breaks ASP.NET Core at startup
• If I use ILogger, the function breaks at trigger.

Someone already came across this issue, and references a commit that may be the cause.

https://www.neovolve.com/2018/04/05/dependency-injection-and-ilogger-in-azure-functions/

Here is a repo that I created that has the issue. I can answer any questions if needed.
https://github.com/isaac2004/AzureMediaServicesDemo

[sanderaernouts]

@isaac2004 I did something very similar based on your example repo.The only difference is that I injected the ILoggerFactory into the function trigger. You can then use ILoggerFactory.CreateLogger(..) to create the required logger. I then went on and configured and IServiceProvider like this:

public static class ServiceProviderConfig
{
    public const string LogCategoryHost = "Host";
    public const string LogCategoryFunction = "Function";
    public const string LogCategoryWorker = "Worker";
    public const string LogCategoryCustom = "CustomPrefix"; //your custom assembly prefix
    
    public static IServiceProvider Configure(ExtensionConfigContext context)
    {
        var startup = new Startup();
        var configBuilder = new Microsoft.Extensions.Configuration.ConfigurationBuilder();
        var serviceCollection = new ServiceCollection();
        
        var factory = context.Config.LoggerFactory;

        if (factory == null)
        {
            throw new InvalidOperationException($"{nameof(context.Config.LoggerFactory)} in {nameof(ExtensionConfigContext)} cannot be null. Unable to refresh log filters");
        }

        var refreshFilters = factory.GetType().GetMethod("RefreshFilters", BindingFlags.NonPublic | BindingFlags.Instance);

        if (refreshFilters == null)
        {
            throw new InvalidOperationException(
                $"Could not load private method RefreshFilters(..) from {factory.GetType().FullName}");
        }

        var filterOptions = new LoggerFilterOptions();
        filterOptions.AddFilter((category, level) =>
        {
            return category.StartsWith($"{LogCategoryHost}.") ||
                    category.StartsWith($"{LogCategoryFunction}.") ||
                    category.StartsWith($"{LogCategoryWorker}.") ||
                    category.StartsWith($"{LogCategoryCustom}.");
                    //you can add more here off course
        });

        refreshFilters.Invoke(factory, new[] {filterOptions});



        startup.Configure(configBuilder);

        IConfiguration configuration = configBuilder.Build();
        serviceCollection.AddSingleton(configuration);
        serviceCollection.AddSingleton(factory);
        serviceCollection.AddLogging(builder =>
            {
                builder.AddFilter((category, level) =>
                    category.StartsWith("Kongsberg") || category.StartsWith("Hangfire"));
            });

        startup.ConfigureServices(serviceCollection);
        
        return serviceCollection.BuildServiceProvider(true);
    }

    
}

I added a Startup.cs just so it's a bit more like aspnetcore:

public class Startup
{
    public void ConfigureServices(IServiceCollection services)
    {
        //add your services here
    }
    
    public void Configure(IConfigurationBuilder app)
    {
        //setup configuration here
    }
    
}

I have added services in the ConfigureServices that require and ILogger<T> and these get injected as expected even in the function trigger.

public static class ScheduleDeploymentJobsQueueTrigger
{
    [FunctionName("ScheduleDeploymentJobs")]
    public static async Task Run([QueueTrigger("...", Connection = "...")]string input, ExecutionContext context, [Inject(typeof(ILoggerFactory))]ILoggerFactory loggerFactory, [Inject(typeof(DeploymentJobScheduler))]DeploymentJobScheduler scheduler)
    {
        try
        {
            ...
        }
        catch (Exception ex) when (LogError(loggerFactory, ex))
        {   
            throw;
        }
    }

    private static bool LogError(ILoggerFactory factory, Exception exception)
    {
        var logger = factory.CreateLogger(typeof(ScheduleDeploymentJobsQueueTrigger).FullName);
        logger.LogCritical(exception, exception.Message);

        return true;
    }
}

In this example, DeploymentJobScheduler requires an ILogger<DeploymentJobScheduler> which gets injected as expected. I use the logger factory only to log exceptions that occur inside the trigger.

Hope this helps others that are facing the same issue currently 👍 .

[vsadams]

@sanderaernouts is that using the latest version of the v2 function runtime? Also, I tried a similar approach but instead of injecting the factory I just requested an ILogger from the IOC and in the registration I just created a logger from the factory. The problem I had was that even though I got a logger from the factory, it was very obvious it wasnt the correct Logger wrapper, it wouldnt log anything.

[sanderaernouts]

@vsadams think so:

But you are right, the loggers get injected as expected but do not log anything but the default function logging. I did not notice that one yet..

The problem is in Utility.cs in the azure-functions-host. It sets adds filters that do not allow anything but logging from the function:
Line 408:

public static LoggerFilterOptions CreateLoggerFilterOptions()
{
    // TODO: Whitelist should be configurable
    // Whitelist our log categories to remove large amounts of ASP.NET logs.
    var filterOptions = new LoggerFilterOptions();
    filterOptions.AddFilter((category, level) => category.StartsWith($"{ScriptConstants.LogCategoryHost}.") || category.StartsWith($"{ScriptConstants.LogCategoryFunction}.") || category.StartsWith($"{ScriptConstants.LogCategoryWorker}."));

    return filterOptions;
}

As you can see there is still a to-do statement in there that whitelisting should be configurable. I have updated my original comment with a way to update the filters through reflection, but that is a bit hacky.
This does the trick:

var factory = context.Config.LoggerFactory;

if (factory == null)
{
    throw new InvalidOperationException($"{nameof(context.Config.LoggerFactory)} in {nameof(ExtensionConfigContext)} cannot be null. Unable to refresh log filters");
}

var refreshFilters = factory.GetType().GetMethod("RefreshFilters", BindingFlags.NonPublic | BindingFlags.Instance);

if (refreshFilters == null)
{
    throw new InvalidOperationException(
        $"Could not load private method RefreshFilters(..) from {factory.GetType().FullName}");
}

var filterOptions = new LoggerFilterOptions();
filterOptions.AddFilter((category, level) =>
{
    return category.StartsWith($"{LogCategoryHost}.") ||
            category.StartsWith($"{LogCategoryFunction}.") ||
            category.StartsWith($"{LogCategoryWorker}.") ||
            category.StartsWith($"{LogCategoryCustom}.");
            //you can add more here off course
});

refreshFilters.Invoke(factory, new[] {filterOptions});

@brettsam @fabiocav will whitelisting of logging categories be added any time soon? And isn't it possible to blacklist ASP.NET instead of whitelisting the function logging categories? That way custom logging categories will not be filtered out.

[isaacrlevin]

@sanderaernouts yep this was called out in that blog post I referenced earlier. This is pretty large barrier for DI to work in Functions. I figure the team is working on this currently as DI is one of the top TODOs for Azure Functions.

[isaacrlevin]

@sanderaernouts do you have a repo to share for this?

[sanderaernouts]

@isaac2004 now I do, you can find it here:
https://github.com/sanderaernouts/azure-functions-v2-di

FYI: based on this blog post you mentioned earlier I tried to create a LoggerFactoryAdapter by implementing ILoggerFactory and forwading all calls to the logger factory available in the ExtensionConfigContext. With the only change that CreateLogger(string categoryName) would change the category name to Functions.{categoryName}.User as the blog post suggests. But I could not get it to work, so I reverted back to using reflection to refresh the FilterOptions on the factory.

[isaacrlevin]

@sanderaernouts good stuff, but do you need configuration in localsettings.json to get loggin to work locally? Your sample does not log when local debugging.

[sanderaernouts]

@isaac2004 no localsettings.json is not required. I run the functions app locally from VS then I trigger the function by running Invoke-WebRequest -Uri "http://localhost:7071/api/Function1" from a Powershell command prompt and I see this logging in the console:

These are the two logging statements I added to this example.

[isaacrlevin]

@sanderaernouts oddly enough, if you move your service into a .NET Standard library, it does not log.
Seems it is an issue with the filter.

[moritonal]

To anyone finding this issue the same way I did, you can add the ILogger via DI as follows:

The following must go in your Startup.cs

private void ConfigureServices(IServiceCollection services)
{
    services.AddLogging();
}

This adds ILoggerFactory and ILogger<> to the DI, which means your resolving classes must use ILogger as follows:

public CalculatorService(ILogger<CalculatorService> logger) {
    ...
}

Share and enjoy
Tom

[felpel]

@Glitch0011 note that this will work in practice but the logs will be left out in AppInsights, but you should be able to output logs in the console locally if you register the proper logger in the DI services.

[jeremy001181]

@sanderaernouts is this still the case? it seems like in the latest release v2.0.12332 the Utility.cs class has been completely rewritten?

@vsadams think so:

But you are right, the loggers get injected as expected but do not log anything but the default function logging. I did not notice that one yet..

The problem is in Utility.cs in the azure-functions-host. It sets adds filters that do not allow anything but logging from the function:
Line 408:

public static LoggerFilterOptions CreateLoggerFilterOptions()
{
    // TODO: Whitelist should be configurable
    // Whitelist our log categories to remove large amounts of ASP.NET logs.
    var filterOptions = new LoggerFilterOptions();
    filterOptions.AddFilter((category, level) => category.StartsWith($"{ScriptConstants.LogCategoryHost}.") || category.StartsWith($"{ScriptConstants.LogCategoryFunction}.") || category.StartsWith($"{ScriptConstants.LogCategoryWorker}."));

    return filterOptions;
}

As you can see there is still a to-do statement in there that whitelisting should be configurable. I have updated my original comment with a way to update the filters through reflection, but that is a bit hacky.
This does the trick:

var factory = context.Config.LoggerFactory;

if (factory == null)
{
    throw new InvalidOperationException($"{nameof(context.Config.LoggerFactory)} in {nameof(ExtensionConfigContext)} cannot be null. Unable to refresh log filters");
}

var refreshFilters = factory.GetType().GetMethod("RefreshFilters", BindingFlags.NonPublic | BindingFlags.Instance);

if (refreshFilters == null)
{
    throw new InvalidOperationException(
        $"Could not load private method RefreshFilters(..) from {factory.GetType().FullName}");
}

var filterOptions = new LoggerFilterOptions();
filterOptions.AddFilter((category, level) =>
{
    return category.StartsWith($"{LogCategoryHost}.") ||
            category.StartsWith($"{LogCategoryFunction}.") ||
            category.StartsWith($"{LogCategoryWorker}.") ||
            category.StartsWith($"{LogCategoryCustom}.");
            //you can add more here off course
});

refreshFilters.Invoke(factory, new[] {filterOptions});

@brettsam @fabiocav will whitelisting of logging categories be added any time soon? And isn't it possible to blacklist ASP.NET instead of whitelisting the function logging categories? That way custom logging categories will not be filtered out.

[VaclavElias]

Any update on this? I also would like to log :)

[himalpatel81]

Any update on this ?

[minidfx]

This is very confusing for me because I've my own ServiceProvider containig my singletons for the host, for instance the HttpClientFactory containing states(HttpClientHandlers) but I potentially I receive a new ILogger instance for each execution.

A scope is created at each execution of the function to isolate some states between functions, for instance the DbContext.

Because we received a new ILogger potentially each time, I'm not able to use my singletons using the DI, I've a new ServiceProvider built each time to inject the given ILogger into the container. It works well excepted that now I've the warning: More than twenty 'IServiceProvider' instances have been created for internal use by Entity Framework because EF Core keep a state in the ServiceProviderCache hidden static.

From my point of view is wrong to keep ServiceProviders cached in EF Core because we cannot trust the Scope lifetime in this case, even if we Dispose the ServiceProvider.

My Scope and ServiceProvider are disposed each time then I expected to be able to inject a new ILoggerFactory each time too.

Then how can I use your ILogger instance with my DI configuration and your DbContext which keep an older ILogger potentially and a different ILoggerFactory.

I've a problem because I'm not able to inject the given ILogger into a Singleton ILoggerFactory which is needed by EF Core otherwise it will create a new ServiceProvider each time and thrown the warning More than twenty 'IServiceProvider' instance ... bla bla.

I already tried to use another logging system but no other one works as well than the injected one in the Azure function to log correctly, warning, trace, debug everywhere (interactive console and AI)

[minidfx]

This is very confusing for me because I've my own ServiceProvider containig my singletons for the host, for instance the HttpClientFactory containing states(HttpClientHandlers) but I potentially I receive a new ILogger instance for each execution.

A scope is created at each execution of the function to isolate some states between functions, for instance the DbContext.

Because we received a new ILogger potentially each time, I'm not able to use my singletons using the DI, I've a new ServiceProvider built each time to inject the given ILogger into the container. It works well excepted that now I've the warning: More than twenty 'IServiceProvider' instances have been created for internal use by Entity Framework because EF Core keep a state in the ServiceProviderCache hidden static.

From my point of view is wrong to keep ServiceProviders cached in EF Core because we cannot trust the Scope lifetime in this case, even if we Dispose the ServiceProvider.

My Scope and ServiceProvider are disposed each time then I expected to be able to inject a new ILoggerFactory each time too.

Then how can I use your ILogger instance with my DI configuration and your DbContext which keep an older ILogger potentially and a different ILoggerFactory.

I've a problem because I'm not able to inject the given ILogger into a Singleton ILoggerFactory which is needed by EF Core otherwise it will create a new ServiceProvider each time and thrown the warning More than twenty 'IServiceProvider' instance ... bla bla.

I already tried to use another logging system but no other one works as well than the injected one in the Azure function to log correctly, warning, trace, debug everywhere (interactive console and AI)

Ok to be able to use my own DI container injecting the ILogger given by the Azure Function and to avoid a memory leak with the EF Core DbContext, I call the UseInternalServiceProvider extension method to pass my ServiceProvider to EF Core, then no more ServiceProviders cached and no more warnings because 20 ServiceProvider were created.

[oatsoda]

I'm using the new FunctionStartup Dependency Injection for Functions and was also having this problem.

ILogger injected into the Functions "Run" methods themselves worked fine. But when I added ILogger<T> to a type T which was injected by DI, it would not log. The instance of ILogger<T> itself was injected OK, but no logs were written to the output.

However, it turns out that the issue was simple for me: I needed to add the logging settings to the host.json file.:

"Logging": {
  "LogLevel": {
    "Default": "Warning"
  }
}

Presumably, this means that the ILogger direct from the Functions is not bound by the logging config (or the default settings allow it to log) whereas for other "Categories" (i.e. T) the default is None, meaning no logging is output.

[brettsam]

I'm going to close this now as you can request an ILogger<T> in any DI-registered service, and you'll get one that's wired up to all the logging that the functions host uses. https://docs.microsoft.com/en-us/azure/azure-functions/functions-dotnet-dependency-injection

@oatsoda points out that the logging filter settings may need tweaking (due to #4345).

See some of my comments here for some more descriptions (and doc links) for how to get this working. For the most part, .NET Core DI and Logging docs apply to Functions as well.

• ILogger is not injected when using new DI functionality #4425 (comment)
• ILogger is not injected when using new DI functionality #4425 (comment)
• ILogger is not injected when using new DI functionality #4425 (comment)

[npruessner]

I'm using the new FunctionStartup Dependency Injection for Functions and was also having this problem.

ILogger injected into the Functions "Run" methods themselves worked fine. But when I added ILogger<T> to a type T which was injected by DI, it would not log. The instance of ILogger<T> itself was injected OK, but no logs were written to the output.

However, it turns out that the issue was simple for me: I needed to add the logging settings to the host.json file.:

"Logging": {
  "LogLevel": {
    "Default": "Warning"
  }
}

Presumably, this means that the ILogger direct from the Functions is not bound by the logging config (or the default settings allow it to log) whereas for other "Categories" (i.e. T) the default is None, meaning no logging is output.

This worked perfectly for me. Although the code you pasted is a little different for newer versions. Here is what I added to the host.json file in order to get ILogger DI to work properly.

{
  "logging": {
    "logLevel": {
      "default": "Information",
      "Host.Results": "Error",
      "Function": "Error",
      "Host.Aggregator": "Trace"
    }
  },
  "version": "2.0"
}

Update: Removed "fileLoggingMode":"always" based on below comment.

[paulbatum]

Just a small side note. I do not recommend the part of the above config that sets fileLoggingMode to always. This will have a significant perf impact in production (writing logs to the filesystem is expensive).

[M0ns1gn0r]

@npruessner does it really need all these settings? The "default": "Information" seems to actually be enough.

[npruessner]

@npruessner does it really need all these settings? The "default": "Information" seems to actually be enough.

Most likely not. I think it's the structure that's important. I'm sure there are defaults if you don't supply a value.