DependencyContextAssemblyFinder.FindAssembliesContainingName Throws on GetDefaultAssemblyNames

[CreepyGnome]

Okay so this is regarding the following class and its method FindAssembliesContainingName:

serilog-settings-configuration/src/Serilog.Settings.Configuration/Settings/Configuration/Assemblies/DependencyContextAssemblyFinder.cs

This all started when implementing Serilog with my ASP.NET Core Web API services and when I got to adding the JSON Configuration settings the .Configuration(Configuration) extension method called as so new LoggerConfiguration() .ReadFrom.Configuration(Configuration) it would throw a FileLoadException: The given assembly name or codebase was invalid.

I couldn't figure out why as I have all the required Serilog dependencies from your readme, and I can get it working in a clean new API.NET Core Web API project, just not any of the real-world production projects.

I walked through the stack trace and found that it was in your DependencyContextAssemblyFinder.FindAssembliesContainingName when it calls GetDefaultAssemblyNames when the Linq query is executed on the ToList() call.

If I remove the second from it doesn't throw and when I compared what it is doing I am not sure why the second from is even there to guard against or what is gained with it.

For example here is the results returned from the default template project where it works as-is:

Serilog Serilog.AspNetCore Serilog.Enrichers.Environment Serilog.Enrichers.Thread Serilog.Extensions.Logging Serilog.Settings.Configuration Serilog.Sinks.Console Serilog.Sinks.File

And here are the results when you remove that second from in that project and in my production project where it would throw if it was there:

Serilog Serilog.AspNetCore Serilog.Enrichers.Environment Serilog.Enrichers.Thread Serilog.Extensions.Logging Serilog.Settings.Configuration Serilog.Sinks.Console Serilog.Sinks.File

As you can see they are 100% the same results so not sure what is the purpose or what is gained with the second from.

I would suggest that we change this:

public override IReadOnlyList<AssemblyName> FindAssembliesContainingName(string nameToFind)
{
    var query = from library in _dependencyContext.RuntimeLibraries
                from assemblyName in library.GetDefaultAssemblyNames(_dependencyContext)
                where IsCaseInsensitiveMatch(assemblyName.Name, nameToFind)
                select assemblyName;

    return query.ToList().AsReadOnly();
}

To this:

public override IReadOnlyList<AssemblyName> FindAssembliesContainingName(string nameToFind)
{
    var query = from library in _dependencyContext.RuntimeLibraries
                where IsCaseInsensitiveMatch(library.Name, nameToFind)
                select assemblyName;

    return query.ToList().AsReadOnly();
}

I would be more than happy to make a PR for this just wanted to check to find out if I am missing something for this line of code from assemblyName in library.GetDefaultAssemblyNames(_dependencyContext) before doing it. As this is a blocking issue for me on being able to use this NuGet package. I am not familiar enough with DependencyContext and the DependcyModel extensions to know how to provide my own instead of the default one that is being used. Your readme doesn't touch on this except to state it uses it and that's it.

[skomis-mm]

Hi, @CreepyGnome , thanks for the report. Can you please share on what Library the method throws? The reason for two from is because there can be multiple assemblies per library. We should probably filter out such assets (native libraries?)

[CreepyGnome]

I couldn't figure it out as it isn't logged. I tried enabling Fusion logs but couldn't get it working with .NET Core. I also enabled COREHOST_TRACE=1 and didn't get any additional details about the exception, although I could at least see the exception in this log.

The full stack trace is below.

I don't understand enough about the new DependencyContext stuff to be able to properly respond to:

The reason for two from is because there can be multiple assemblies per library.

But if I am to guess you ask the DependencyContext for all its RuntimeLibraries and then you ask each one of those for its Default Assembly Names (couldn't find docs on this in Microsoft Land for that method) and you are trying to find all the assemblies that have Serilog in their name from those. Then returning all the ones matching ones use the original RuntimeLibrary name.

As I said not sure what we gain here as without doing that it still returns the same results every time I try it in different projects. Even ones, that have plenty of NuGet and Project references for dependencies.

You provide a way to provide a DependencyContext so that it would not use the default, however not sure how to create/generate one that would work in this situation.

System.IO.FileLoadException: The given assembly name or codebase was invalid. (Exception from HRESULT: 0x80131047)
   at System.Reflection.AssemblyName.nInit(RuntimeAssembly& assembly, Boolean raiseResolveEvent)
   at System.Reflection.AssemblyName..ctor(String assemblyName)
   at Microsoft.Extensions.DependencyModel.DependencyContextExtensions.GetAssemblyName(String assetPath)
   at System.Linq.Enumerable.SelectArrayIterator`2.MoveNext()
   at System.Linq.Enumerable.SelectManyIterator[TSource,TCollection,TResult](IEnumerable`1 source, Func`2 collectionSelector, Func`3 resultSelector)+MoveNext()
   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.ToList()
   at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
   at Serilog.Settings.Configuration.Assemblies.DependencyContextAssemblyFinder.FindAssembliesContainingName(String nameToFind)
   at Serilog.Settings.Configuration.ConfigurationReader.LoadConfigurationAssemblies(IConfigurationSection section, AssemblyFinder assemblyFinder)
   at Serilog.Settings.Configuration.ConfigurationReader..ctor(IConfigurationSection configSection, AssemblyFinder assemblyFinder, IConfiguration configuration)
   at Serilog.ConfigurationLoggerConfigurationExtensions.Configuration(LoggerSettingsConfiguration settingConfiguration, IConfiguration configuration, String sectionName, DependencyContext dependencyContext)

[CreepyGnome]

So what I have learned in the last 24 hours and mostly in the last couple of hours is that DependencyContext.Default.RuntimeLibraries appears to be a replacement for the full framework AppDomain.CurrentDomain.GetAssemblies. And instead of returning an Assembly instance that was a fully loaded assembly, it not returns AssemblyName instances which is much lighter weight.

My current understanding is that DependencyContext.Default.RuntimeLibraries is the flattened listed of all the libraries, not just the directly referenced ones in the project file. I did a quick test and this appears to be the case. So at this time I am not sure if anything is gained or of value with the from assemblyName in library.GetDefaultAssemblyNames(_dependencyContext) line.

[CreepyGnome]

If the library.GetDefaultAssemblyNames is to stay it probably shouldn't be called for all library instances. Maybe only call it if it any of the library dependencies reference Serilog and then you know it is probably safe. As it is getting called on all the libraries as the where filter requires its results to be used. As it then means EVERY name is being sent to AssemblyName to be constructed which may not be good in all cases.

This may be a solution that would work for the reasons that where the original intentions but was not what was actually being done. How about this for the new method. It works for me currently in all my services where the original does not.

public override IReadOnlyList<AssemblyName> FindAssembliesContainingName(string nameToFind)
{
    var query = from library in _dependencyContext.RuntimeLibraries
                where IsReferencing(library, nameToFind)
                from assemblyName in library.GetDefaultAssemblyNames(_dependencyContext)
                where IsCaseInsensitiveMatch(assemblyName.Name, nameToFind)
                select assemblyName;

    return query.ToList().AsReadOnly();
}

// New method added to AssemblyFinder base class
protected static bool IsReferencing(Library library, string textToFind)
{
    return library.Dependencies.Any(dependency => dependency.Name.ToLowerInvariant().Contains(textToFind.ToLowerInvariant()));
}

[skomis-mm]

Maybe only call it if it any of the library dependencies reference Serilog and then you know it is probably safe. As it is getting called on all the libraries as the where filter requires its results to be used. As it then means EVERY name is being sent to AssemblyName to be constructed which may not be good in all cases.

👍 The original intention was to get configuration assemblies by convention ("serilog" in the assembly name). It seems make sense to filter by RuntimeLibrary name since it is an abstraction for a nuget package whose assemblies are used at the runtime.

The ugly workaround:

internal class WrapperContext : DependencyContext
{
     public WrapperContext(DependencyContext dc, Predicate<RuntimeLibrary> filter)
         : base(dc.Target, dc.CompilationOptions, dc.CompileLibraries, dc.RuntimeLibraries.Where(x => filter(x)), dc.RuntimeGraph)
        {
        }
}

...
var logger = new LoggerConfiguration()
     .ReadFrom.Configuration(configuration, new WrapperContext(DependencyContext.Default, r => r.Name.ToLower().Contains("serilog")))
     .CreateLogger();

[CreepyGnome]

@skomis-mm That WrapperContext does work to get around the issue which is great for now.

The solution I provided in the comment https://github.com/serilog/serilog-settings-configuration/issues/195#issuecomment-521800233 does seem to work and I think if you need to keep that second from that it achieves the goal without the risk of trying to create an invalid AssemblyName instance.

[skomis-mm]

@CreepyGnome feel free to add PR, the solution above seems right addition

[CreepyGnome]

@skomis-mm sounds good I will do that... should I PR to dev or master?

[skomis-mm]

@CreepyGnome dev. Master is for stable releases

[CreepyGnome]

@skomis-mm the tests without any changes on latest dev have 53 failed tests, not sure if it is safe to add anything to it if so many of the tests are not passing before I even make changes. Hard to know if I broke something or not in this state.

You or someone with more familiarity with your tests and process is free to take the changes shown above. I updated them to be more in line for a copy and paste if needed.

[nblumhardt]

@CreepyGnome grabbed the latest, they all pass for me:

This is the last CI build for dev - https://ci.appveyor.com/project/serilog/serilog-settings-configuration/builds/25014971 - looks okay.

What failures are you hitting?

[CreepyGnome]

@nblumhardt I am using Visual Studio 2017 and its built-in test runner. One issue is your screenshot shows only 100 tests ran and passed. The test runner is finding 201 tests with 148 passing and 53 failing. I assume that your CI is only running some of the tests and not all of the tests.

All of them seem to be failing because of the following error.

System.IO.FileLoadException : Could not load file or assembly 'Microsoft.Extensions.Configuration, Version=1.1.1.0, Culture=neutral, PublicKeyToken=adb9793829ddae60' or one of its dependencies. The located assembly's manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040)

Maybe the CI process is manually excluding old or bad tests or just running tests from a specific folder or something.

[nblumhardt]

Hi Rodney,

No, the screenshot and CI output both show all 201 - there are 101 tests for one TFM, and 100 tests for the other. The VS test runner adds these two numbers and displays the total.

VS 2017 might be having some trouble with the new-style projects?

Since the failures are in the .NET Framework (net452) configuration on your machine, there could alternatively be a GAC issue; or, you might not have the required SDKs installed.

Running ./Build.ps1 from the command-line might do the job - worth a try.

Best regards, Nick

[CreepyGnome]

@nblumhardt I see my mistake that it ran two sets of tests one against full framework, and the other against .net core.

The project cs file looks correct for VS to run them correctly and the test runner shows they are running them in net452 and netcoreapp2.0 accordingly. I also said the wrong version of VS, I am using Visual Studio 2019 (16.2.2), I typed 2017 out of an old habit I guess.

I am also on Windows 10 (1903) and it comes with .NET Framework 4.8. But when I installed VS2019 I installed the targeting packs for 4.0 through to 4.7.2. However, the only .NET 4.x SDKs that were installed with VS was 4.7.2.

As for Microsoft.Extensions.Configuration.dll v1.1.1 its looking for its not a GAC assembly its a .NET Standard v1.1 libary via NuGet. And the Microsoft.Extensions.Configuration.Json and Microsoft.Extensions.Configuration.Abstractions are included in the csproj for the test for both net452 and netcoreapp2.0. The json package depends on the one its complaining about and should be pulled in by NuGet. So this is not a GAC issue as it is complaining about NuGet packages.

NuGet restore is running and getting them, and I can see that they are there and available. They are in the bin folder, and its version 1.1.2 though. However, it can be any child dependency failing when it tries to load that one that could cause the error.

So I can assume its probably an environmental issue, as the tests may not have been designed to work with VS2019 or the built-in test runner probably. Since you guys probably rely on the CICD process to do it.

[skomis-mm]

Hi, @CreepyGnome , I was able to reproduce this in VS 2019. If you update Microsoft.NET.Test.Sdk package to the latest version (16.2.0) tests should pass from the test explorer of VS 2019

[CreepyGnome]

Hi @skomis-mm,

That's great, however, isn't this technically a new issue as the tests are broken in the current dev branch when using the Microsoft Test runner to run them or do you not support using the IDE as a test runner? If so then it's not a supported issue, however, I hope that is not the case as external committers would typically try or prefer to use the built-in test runner.

The Test SDK versions while they appear to align with Visual Studio versions they are not really aligned and 16.x Test SDK will work just fine with any version of VS2017.

I can try to find some time again to doing the PR and updating the tests if you are okay with the PR including also the fix for the unrelated broken tests. Or would you rather it have a separate PR for just fixing the broken tests due to the SDK by updating the libraries and then another PR after that for the original issue we worked through here?

[skomis-mm]

@CreepyGnome ,

The IDE test runner should be supported IMO, but I believe the last time it was tested before VS 2019 launch. I think the problem is with 15.0.0 Test SDK with VS 2019. But later versions of SDK are backward compatible as you pointed (e.g. 16.2.0 with VS2017)

I think this change can be combined in single PR since its a tiny change (update PackageReference in the csproj) or it can be separate if you want so.