COREHOST_TRACE should log AssemblyLoadContext

[jzabroski]

Background
On Windows, I am integrating with a .NET Core global tool that in turn loads assemblies via command line parameter assembly="c:\source\bin\Debug\netstandard2.0\JohnZabroski.Database.dll". JohnZabroski.Database.dll transitively references System.Data.SqlClient.

Problem
With COREHOST_TRACE=1, my current stderr looks like this:

!!! Could not load file or assembly 'System.Data.SqlClient, Version=4.5.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'. Could not find or load a specific file. (Exception from HRESULT: 0x80131621)
!!! +- Could not load file or assembly 'System.Data.SqlClient, Version=4.5.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'.

Unhandled Exception: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.IO.FileLoadException: Could not load file or assembly 'System.Data.SqlClient, Version=4.5.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'. Could not find or load a specific file. (Exception from HRESULT: 0x80131621) ---> System.IO.FileLoadException: Could not load file or assembly 'System.Data.SqlClient, Version=4.5.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a'.
   at System.Runtime.Loader.AssemblyLoadContext.LoadFromPath(IntPtr ptrNativeAssemblyLoadContext, String ilPath, String niPath, ObjectHandleOnStack retAssembly)
   at System.Runtime.Loader.AssemblyLoadContext.LoadFromAssemblyPath(String assemblyPath)
   at System.Reflection.Assembly.LoadFrom(String assemblyFile)
   at System.Reflection.Assembly.LoadFromResolveHandler(Object sender, ResolveEventArgs args)
   at System.AppDomain.InvokeResolveEvent(ResolveEventHandler eventHandler, RuntimeAssembly assembly, String name)

I found the following blogpost to be rather intimidating when trying to troubleshoot WHY my assembling could not be found or located: https://mattwarren.org/2016/07/04/How-the-dotnet-CLI-tooling-runs-your-code/

I have found Assembly Fusion Log Viewer tool in .NET 4.6 to be A LOT easier user experience. See: https://github.com/dotnet/coreclr/issues/10379

Possibly related
https://github.com/dotnet/coreclr/issues/15863 - users find debugging assembly loading on Linux to be awful (fixed: dotnet/coreclr#15831)

[RussKeldorph]

Starting with @jeffschwMSFT. Please fix area- if I'm wrong.

[jeffschwMSFT]

This is absolutely needed. It is on our backlog, but it is not likely going to make .NET Core 3.0.

[IanKemp]

This is absolutely needed. It is on our backlog, but it is not likely going to make .NET Core 3.0.

If it is "absolutely needed", why won't it be in Core 3.0? Shipping new and fancy features is great, but Microsoft's strength has always been in the tools to debug those features when they don't work. Troubleshooting assembly bind failures is a critical tool that should been built into Core from day one, and the fact that it wasn't and apparently still isn't seen as a priority is both concerning and, quite frankly, embarrassing.

[jzabroski]

@jeffschwMSFT @vitek-karas Any chance this can get looked at again? I know that Vitek explained (in the linked Merged dotnet/docs PR above) some of the reasons why things are different in the new runtime environment than legacy .NET <=4.8.

[vitek-karas]

In .NET 5+ we added detailed tracing from the assembly loader. See this guide how to get the trace and how to understand it: https://docs.microsoft.com/en-us/dotnet/core/dependency-loading/collect-details.

This would provide detailed information of what exactly the runtime was asked to do (load assembly from which file or why it failed and so on). COREHOST_TRACE is probably not going to help much in this case. I would guess that the tool loads the plugin via Assembly.LoadFrom which will always load into the default ALC.

[jzabroski]

@vitek-karas This looks great. To confirm, it sounds like while dotnet-trace has existed from the very beginning, it was not until .net 5.0 that it could take advantage of the eventpipe events around assembly loading?

I think what would be great is an article that explains to open source authors how to troubleshoot issues that seem like assembly binding issues across various runtimes and hosts. I have a rough idea of how to do that, but a consistent approach would make it easier for me to say, "Ok, this is a bug in my project" vs, "Ok, this is a bug in some .NET project owned by Microsoft" even if the line is pretty gray/blurry.

[jzabroski]

dotnet-trace collect --providers Microsoft-Windows-DotNETRuntime:4 --process-id <pid>

Also, how do I trace an exe? It seems like the ideal scenario is for dotnet-trace to launch the executable so it can immediately trace it, similar to windbg. Most assembly loading events take place in the HostBuilder which is like the first nanoseconds of a process's existence, so needing to pass process-id seems like a oversight?

Also, is it a typo that it says 4 for the providers version? Or a legacy detail?

[jzabroski]

BTW, if you can point me to the repo where dotnet-trace lives, happy to submit a PR to add that feature.

[vitek-karas]

dotnet-trace lives in https://github.com/dotnet/diagnostics.

You can run it like:

dotnet-trace collect --providers Microsoft-Windows-DotNETRuntime:4 -- myapp.exe argument1

It will start myapp.exe argument1 and attach to it.

[jzabroski]

Great, I will update the doc you linked to include that example as I think its the more common one in my experience. Thank you so much.

[vitek-karas]

I was just about to do that - but I'll be more than happy if you do it. I found this as the docs on that feature: https://github.com/dotnet/diagnostics/blob/main/documentation/dotnet-trace-instructions.md#using-dotnet-trace-to-launch-a-child-process-and-trace-it-from-startup

Note: It's not in the doc because when we were writing it, dotnet-trace could not do this yet 😉

[vitek-karas]

Also if you think this answered your question could you please close this issue?

[jzabroski]

Yep, was just about to go do that.