Log details of app being launched by dotnet(.exe) to ETW/LTTng

[DamianEdwards]

There is a desire in certain environments to get details about .NET Core apps being launched in order to aid in analysis of issues, distribution of frameworks and dependencies being loaded, etc. (similar to the way that .NET apps log to the Windows Event log when they crash to capture details of failure). This can be particularly useful to discover how many apps are using a given shared framework version (to aid in planning to uninstall that version), or which apps are using a particular dependency (in case there is a security or compliance issue of some kind).

To this end, the host layer should log details about the app being launched to the appropriate sink for the OS (e.g. ETW on Windows, LTTng on Linux). The following details would be helpful:

• Path and version of dotnet host
• Path, name and version of any shared frameworks depended on by the application, including details of whether the app will run on that version or be rolled forward to a newer version
• Path and contents of any additional deps being applied
• Names and versions of any dependencies declared by the application in its deps file
• Name and version of the application assembly
• Path of the application assembly

It might be good to enable configuring which of these details is logged, e.g. via ETW event names or keywords.

[Petermarcu]

@brianrob

[DamianEdwards]

Would like this to be considered for next minor release, or even better, a servicing release 😄

[brianrob]

CoreCLR has the concept of the RuntimeInformation event which does a stripped-down version of this for things that the runtime knows, and it is quite valuable. This is what is logged in the RuntimeInformation event:

• Runtime version
• Path to coreclr.dll/libcoreclr.so
• Startup flags
• Command line (not always populated in the case of CoreCLR)
• COM object GUID

It can be quite useful and I can imagine that the information requested here would also be quite valuable. One thing to note is that amost all of the information requested here is information that the host has but the runtime does not. This complicates things just a bit because the component that knows how to log to the platform-dependent and platform-independent loggers is the runtime. I would recommend designing a mechanism to pass this information from the host to the runtime and let the runtime log it. This will guarantee that the information is exposed in all the right logging mechanisms on each platform (both platform-independent and platform-dependent).

I can help with details on exactly what to do here.

[DamianEdwards]

Sounds great.

Where is the RuntimeInformation event logged today?

[brianrob]

It's logged in a few places:

• Runtime start-up
• During rundown (when stopping trace collection) in case we didn't capture or lost the start-up event.

The code that does the actual logging is here: https://github.com/dotnet/coreclr/blob/86f418f0bd196ba84ab702410500271a4f8b0c33/src/vm/eventtrace.cpp#L4926.

It is called from a few different places.

[DamianEdwards]

@blowdart

[blowdart]

Oh yes, I want this for security scanning, including fingerprinting of assemblies (SHA and signer would be great) loaded during startup, and even better, runtime, for dynamic loaded.

[DamianEdwards]

Curious where this has landed? Are we getting this for 3.0?

[jeffschwMSFT]

We are still gathering details on what should be logged. We should put this on the potential list for .NET Core 3.1

[DamianEdwards]

ping ?

[jeffschwMSFT]

It is on our backlog. @DamianEdwards are you the right person to get the specifics on what is needed? We explored this in late .NET Core 3, but the requirements were not solid enough for us to build something.

cc @vitek-karas @elinor-fung @lpereira

[DamianEdwards]

Right owner would be someone on @glennc's team I think, and I know for sure @blowdart is interested too. I provided a strawman summary up front on this issue and I think it's probably still a good place to start.

[swaroop-sridhar]

@vitek-karas, @shirhatti, and @noahfalk talked about this issue. Here are some notes.

• When the host fails to load the runtime, the error logging is limited, since the apphost is a simple native app that cannot take many dependencies. The tracing is limited to:
  • The error logging to console (or upcoming UI message on windows)
  • Tracing information, when the app is actually run with COREHOST_TRACE turned on
• Once the runtime is loaded, we can send ETW, event-pipes, etc.
• In .net core 3/3.1 the host-runtime interface is limited to the host passing a set of strings to the runtime. In .net 5, this will be replaced with a set of callbacks from the runtime to the host -- and therefore, the runtime can expose APIs to request specific information from the host.

Here is the work we agreed to perform in 3.1:

• If/when the runtime is loaded:
  • Log all properties passed to the runtime
  • Log the set of frameworks loaded, along with requested-version and resolved-version for each framework.
• No change in the case where the host fails to load the runtime

This will be achieved by:

• The host writes a string containing the above information as a new property passed to the runtime
• The runtime will generate an event containing all properties passed to it.
• The values of some of the well-known properties may be well-structured (if it is easy enough to do). Otherwise we log the actual strings passed in.

[vitek-karas]

Based on recent offline discussion with @blowdart the security scanning aspect is a somewhat different ask. In addition it might already be sort of "resolved" by existing assembly loader tracing.

[swaroop-sridhar]

For the work agreed upon here, I'm in the process of making the following changes:

• The Host passes a new property FX_RESOLUTION to the runtime. This property is constructed simply as:

    Foreach fx in fx_definitions, 
       Add to FX_RESOLUTION  
             Framework: fx->get_name().c_str(),
             Min: fx->get_requested_version().c_str(),
             Resolved: fx->get_found_version().c_str(),

• A new event RuntimeProperties is added to the runtime, with the schema:

<template tid="RuntimeProperties">
    <data name="ClrInstanceID" inType="win:UInt16" />
    <data name="TRUSTED_PLATFORM_ASSEMBLIES" inType="win:UnicodeString" />
    <data name="NATIVE_DLL_SEARCH_DIRECTORIES" inType="win:UnicodeString" />
    <data name="PLATFORM_RESOURCE_ROOTS" inType="win:UnicodeString" />
    <data name="APP_CONTEXT_BASE_DIRECTORY" inType="win:UnicodeString" />
    <data name="APP_CONTEXT_DEPS_FILES" inType="win:UnicodeString”/>
    <data name="PROBING_DIRECTORIES" inType="win:UnicodeString”/>
    <data name="FX_PRODUCT_VERSION" inType="win:UnicodeString”/>
    <data name="JIT_PATH" inType="win:UnicodeString”/>
    <data name="FX_DEPS_FILE" inType="win:UnicodeString”/>
    <data name="APP_PATHS" inType="win:UnicodeString”/>
    <data name="APP_NI_PATHS" inType="win:UnicodeString”/>
    <data name="FX_RESOLUTION" inType="win:UnicodeString”/>
    <data name="Others" inType="win:UnicodeString”/>

    <UserData>
        <RuntimeProperties xmlns="myNs">
            <ClrInstanceID> %1 </ClrInstanceID>
            <TRUSTED_PLATFORM_ASSEMBLIES> %2 </TRUSTED_PLATFORM_ASSEMBLIES>
            <NATIVE_DLL_SEARCH_DIRECTORIES> %3 </NATIVE_DLL_SEARCH_DIRECTORIES>
            <PLATFORM_RESOURCE_ROOTS> %4 </PLATFORM_RESOURCE_ROOTS>
            <APP_CONTEXT_BASE_DIRECTORY> %5 </APP_CONTEXT_BASE_DIRECTORY>
            <APP_CONTEXT_DEPS_FILES> %6 </APP_CONTEXT_DEPS_FILES>
            <APP_CONTEXT_DEPS_FILES> %6 </APP_CONTEXT_DEPS_FILES>
            <PROBING_DIRECTORIES> %6 </PROBING_DIRECTORIES>
            <FX_PRODUCT_VERSION> %6 </FX_PRODUCT_VERSION>
            <JIT_PATH> %6 </JIT_PATH>
            <FX_DEPS_FILE> %7 </FX_DEPS_FILE>
           <APP_PATHS> %10 </APP_PATHS>
            <APP_NI_PATHS> %11 </APP_NI_PATHS>
            <FX_RESOLUTION> %12 </FX_RESOLUTION>
            <Others> %13 </Others>
        </RuntimeProperties>
    </UserData>
</template>

• The event will be fired on startup, when enabled.

A sample output of the event is here:

TRUSTED_PLATFORM_ASSEMBLIES = C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\3.0.0\Microsoft.AspNetCore.Connections.Abstractions.dll;C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\3.0.0\Microsoft.Extensions.Identity.Stores.dll;C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\3.0.0\Microsoft.AspNetCore.Authentication.dll;webapi\bin\Debug\netcoreapp3.0\publish\asp.dll;C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\3.0.0\Microsoft.AspNetCore.Http.Connections.Common.dll;C:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App\3.0.0\System.Runtime.Serialization.Formatters.dll;C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\3.0.0\Microsoft.AspNetCore.Antiforgery.dll;C:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App\3.0.0\System.IO.IsolatedStorage.dll;C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\3.0.0\Microsoft.AspNetCore.Mvc.Localization.dll;C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\
NATIVE_DLL_SEARCH_DIRECTORIES = C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\3.0.0\;C:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App\3.0.0\;
PLATFORM_RESOURCE_ROOTS = 
FX_DEPS_FILE = webapi\bin\Debug\netcoreapp3.0\publish\asp.deps.json
FX_PRODUCT_VERSION = 3.0.0
APP_CONTEXT_BASE_DIRECTORY = webapi\bin\Debug\netcoreapp3.0\publish\
APP_CONTEXT_DEPS_FILES = webapi\bin\Debug\netcoreapp3.0\publish\asp.deps.json;C:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App\3.0.0\Microsoft.AspNetCore.App.deps.json;C:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App\3.0.0\Microsoft.NETCore.App.deps.json
PROBING_DIRECTORIES = 
JIT_PATH = C:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App\3.0.0\clrjit.dll
FX_RESOLUTION=Framework:'Microsoft.AspNetCore.App', Min:'3.0.0', Resolved:'3.0.0'; Framework:'Microsoft.NETCore.App', Min:'3.0.0', Resolved:'3.0.0'
Othes = System.GC.Server = true

@shirhatti can you please verify if the output is what'd you'd like to have?
@noahfalk, @vitek: Please let me know if you have any additional comments about the implementation. Thanks.

[swaroop-sridhar]

@noahfalk recommended structuring the schema for some items (like TPA, FX_RESOLUTION) as arrays of structured items, rather than strings. I'll update it.

[vitek-karas]

I would change the name of the property in FX_RESOLUTION from Min to Requested, that better describes the intent of the message.

[swaroop-sridhar]

I discussed the logging format issue with @shirhatti, who preferred publishing the runtime properties as simple strings (that are also human readable) rather than binary blobs. So, we'll try implementing the event with data-definitions as individual strings, as described above

[agocke]

@vitek-karas @swaroop-sridhar I'm thinking that this is a 6.0 item now, any objections?

[vitek-karas]

agreed 😢

[swaroop-sridhar]

Me too.

[swaroop-sridhar]

In order to make the event extensible, we'd agreed that the event's payload will contain two arrays -- for property names and values -- similar to what's passed in to the runtime. Initially, we only report the following properties: FX_PRODUCT_VERSION and FX_RESOLUTION, and this can be expanded based on use-cases.

[brianrob]

@swaroop-sridhar do you have a plan for how this data will ultimately get logged? If it gets logged from the runtime, or managed code, we have the ability to use the runtime support for tracing. Is the idea here to extend the interface between the host and the runtime to pass this data, and then the runtime is responsible for logging it?

[swaroop-sridhar]

The FX_RESOLUTION property will be computed by the host, and passed on to the runtime, as an additional property.
The input properties will be logged by the runtime at startup (ex: in CreateAppDomain).
Please see: #644 and #690

[brianrob]

Sounds good. Thanks much @swaroop-sridhar.

[agocke]

I believe this work has been completed in #690

[vitek-karas]

#690 was never merged - as far as I know this functionality doesn't exist in the runtime yet. The only even which is there is Runtime Start - which logs version of CoreCLR and BCL, but nothing else.