Troubleshooting Assembly Load Issues with the MSBuild Structured Log Viewer

As discussed last time, I’d successfully fixed one of the errors that was stopping my console application from running - but there was still one remaining.

The error shown by the log viewer looked superficially similar:

LOG: Using application configuration file: dfcmd.exe.Config
LOG: Redirect found in application configuration file: 4.0.0.0 redirected to 4.3.0.0.
LOG: Post-policy reference: System.Reflection, Version=4.3.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a

This time, however, the version of System.Reflection already matched the version of the NuGet package, so the problem was elsewhere.

Looking in the build folder, I discovered that System.Reflection.dll was missing. For some reason, the build process hadn’t copied that assembly into the build folder as I expected.

To troubleshoot this, I needed to look at the log output of the build. I used the open source MSBuild Log Viewer - a much easier way to view and search MSBuild logs than loading usual text file output into a good text editor.

Generating a binary log file from the build required adding the /binaryLogger option to the msbuild command line:

msbuild /p:Configuration=$buildType /binaryLogger:build.log Document.Factory.2.sln

With this in place, I ran a fresh build, opened the log and searched to see what happened during the build.

With my intitial search finding a few too many results to be useful, I refined the search to look for log entries that contain both “copy” and “system.reflection.dll”. Also, MSBuild logs are hierarchical, and I knew the problem was only within the dfcmd project, so I used a search query that reduced the number of results to a manageable level:

copy system.reflection.dll under(dfcmd)

I found this error, explaining why the assembly wasn’t copied into the build output folder (again, I’ve lightly edited the text for clarity):

Encountered conflict between 'Platform:System.Reflection.dll'
and 'CopyLocal:C:\...\System.Reflection.dll'.
Choosing 'Platform:System.Reflection.dll' because
AssemblyVersion '4.1.2.0' is greater than '4.1.1.0'.

Given that all of my references are to the NuGet package System.Reflection v4.3.0.0, this is somewhat confusing - but at least I’m getting somewhere. It appears the build process is preferring a platform version of the assembly over the locally available copy installed from NuGet.

Looking into the extracted System.Reflection NuGet package, I used a snippet of PowerShell to extract the actual assembly version of the file:

PS> [Reflection.AssemblyName]::GetAssemblyName("C:\...\System.Reflection.dll")

Version        Name
-------        ----
4.1.1.0        System.Reflection

(Where the path passed to GetAssemblyName() is the same path found in the MSBuild log above.)

I found that in this case, the version of the NuGet package doesn’t reflect the version of the assemblies found within. The NuGet package version is v4.3.0.0, but the version of the file within that package targeting .NET 4.6.2 is v4.1.1.0. This doesn’t break any hard rules about the way NuGet works, but given that the vast majority of projects do maintain this correspondence, I didn’t expect this to be the case.

Finding version 4.1.1.0 does explain part of the log message, but where does the v4.1.2.0 come from?

Playing a hunch, based on the prefix Platform:, I used gacutil to search the global assembly cache for System.Reflection:

C:\>gacutil /l system.reflection
Microsoft (R) .NET Global Assembly Cache Utility.  Version 4.0.30319.0
Copyright (c) Microsoft Corporation.  All rights reserved.

The Global Assembly Cache contains the following assemblies:
  system.reflection, Version=4.0.0.0, Culture=neutral,
    PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL

Number of items = 1

This doesn’t appear to be the assembly I’m looking for.