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.



Thursday, May 16, 2019

Thursday Quickie: IoC Registrations done wrong broke my DbContext


TLDR: Using InjectionConstructors in Unity can give you singletons. Beware! (and TEST!)


So our tester at work spotted some InvalidOperationExceptions being logged from our data access library recently indicative of a DbContext being re-used across requests... 

Digging into the registration showed quite a few instance of this sort of code:

container.RegisterType<IService, ServiceImplementation>(
    new TransientLifetimeManager(),
    new InjectionConstructor(new Dependency()));

Spot the mistake?

Passing an InjectionConstructor into RegisterType to specify which constructor on the ServiceImplementation class to use is fine... 

Except that passing new Dependency() to the InjectionConstructor does not indicate that a new instance of the Dependency type should be created for each resolution of IService... instead it creates a singleton instance there and then that's subsequently shared across all instances of the IService. Which is bad.

Of course, for DBContext dependencies this is particularly bad - and is the source of the InvalidOperationException that was detected. It's an easy mistake to make, but one that's really hard to spot until you see those exceptions being logged.

The solution - use InjectionConstructor as it's intended:

container.RegisterType<IService, ServiceImplementation>(
    new TransientLifetimeManager(),
    new InjectionConstructor(
        new ResolvedParameter<Dependency>()));

The ResolvedParameter clause says clearly that you're letting the container decide on the lifetime of Dependency.

For bonus points - and to prevent regressions - write tests that verify both that your composition root / container bootstrapper registers types with the correct lifetimes, and that where you've got DBContexts involved that you get a separate DBContext instance when you resolve two instances of IService.

Whilst the above is specific to the Unity IoC framework, you can be sure that all IoC frameworks will have a similar gotcha - so watch out for your registrations!

Tuesday, April 09, 2019

Tuesday Quickie: When closure bites (or how not to configure Newtonsoft.Json)


TLDR: Be very careful using captured closures and anonymous methods - they can leak memory when you don't expect. Also copy-and-paste code is bad.


So yesterday we had an issue where a long-running service within our platform suddenly started throwing StackOverflowExceptions with a new version. It was a blocker to the next release, so inevitably I got tasked with fixing the issue.

A quick profile of a locally running copy replicated the error (phew!) and pointed to one of our HTTP based service clients being at fault. This was confusing, as those components hadn't changed. 

But what had changed was how those clients were being used - previously, they had accidentally been injected from the IoC container as singletons - now they were being injected as transients.

So why would the stack overflow?

It turns out that the service clients all had copy-and-paste code used to ensure that a custom JSON converter was added to the default JSONSerializerSettings used by the Newtonsoft JSON library, and that code was leaking memory and ultimately causing the StackOverflowException

But how? Here's the old code:



Pretty straightforward - and a static method in a static class shouldn't leak?


WRONG!


On lines 8 and 9 we're capturing a closure (defaultSettings) and then using that within an anonymous method that we're assigning back to JsonConvert.DefaultSettings

Because of the captured closure, the compiler couldn't make the anonymous method truly static - so you get a new instance every time the helper method is called - and those instances are pinned (again because of the captured closure) so that they can't be garbage collected.

Since this helper was being called every time a service client was being instantiated, and the clients were no longer singletons, the profile was showing tens of thousands of instances in memory of Func<JsonSerializerSettings>. Not good.

The solution is to be rather more defensive in adding the converter. Here's the corrected version:


We create our own default JsonSerializerSettings instance and a genuinely static Func<JsonSerializerSettings> helper method on lines 7 & 8.

If JsonConvert.DefaultSettings is null, we assign that helper (within a double-checked lock for safety) on line 18.

Finally, we use whatever helper factory was assigned to get the default JsonSerializerSettings instance (line 23) and add our converter if needed - again within a double-checked lock (line 32).

Re-running the repro resulted in exactly 1 instance of Func<JsonSerializerSettings> being created - and our bug is fixed.

The moral of the story? Watch out for anonymous methods and captured closures - they can bite! 

Friday, March 22, 2019

Friday Quickie: Fixing Kubernetes connectivity with Docker for Windows

Another aide-memoire - when using kubectl on Windows against Docker for Windows you get the following error:

Unable to connect to the server: dial tcp [::1]:8080: connectex: No connection could be made because the target machine actively refused it.

This might well just just be that the tool can't find it's config... and the fix is easy - just set an environment variable:
KUBECONFIG=c:\users\joel\.kube\config
Restart your powershell instance and try again... Simple. (see also this issue in github)

Thursday, February 14, 2019

Thursday Quickie: When AssemblyBinding redirect doesn't... and how I fixed it


TLDR: If your csproj file has AutoGenerateBindingRedirects set to true, then you MUST include the xmlns on the assemblyBinding node for any custom binding redirects in app.config.


So I've been banging my head against the wall trying to get a piece of code delivered over the last few days, and kept hitting an issue where code runs perfectly locally, but when deployed to the target server was failing with the dreaded error
Could not load file or assembly 'System.Net.Http, Version=4.1.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a' or one of its dependencies. The located assembly's manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040)

I'd used Gertjan van Montfoort's excellent article as a guide, but whatever version of the NuGet package I installed, and whatever version I referenced in my binding redirects in app.config, it just would not fire up.

Looking at the Fusion logs (helped by Scott Hanselman's article) I could see that my app was initially loading System.Net.Http from the GAC for a 4.0.0.0 reference, then successfully loaded 4.1.1.3 from the app directory (the one from the NuGet package I referenced).

But when it was trying to load 4.1.1.2 because of other dependencies Fusion was not honouring the binding redirect, and so the app was failing on startup.

Finally I found a comment on the net that hinted about case sensitivity within the app config, so I went looking for differences between my custom redirects and those generated on build into MyApp.exe.config.

And I found one - the generated redirects all have an xmlns attribute on the assemblyBinding node - and my custom one did not

The solution - add one in your app.config


<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <runtime>
    <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">
      <dependentAssembly>
        <assemblyIdentity name="System.Net.Http" publicKeyToken="b03f5f7f11d50a3a" culture="neutral" />
        <bindingRedirect oldVersion="0.0.0.0-4.2.0.0" newVersion="4.1.1.2" />
      </dependentAssembly>
    </assemblyBinding>
  </runtime>
</configuration>

Now your binding redirects get merged with the generated ones and it all works.

My interpretation is that Fusion appears to honour the redirects in assemblyBinding nodes only if all have xmlns attributes or none have them - but not if mixed. 

Hopefully others will find this useful - now I can get on and do some actual work!