DamianEdwards commented 6 years ago

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 commented 6 years ago

@brianrob

DamianEdwards commented 6 years ago

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

brianrob commented 6 years ago

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 commented 6 years ago

Sounds great.

Where is the RuntimeInformation event logged today?

brianrob commented 6 years ago

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 commented 6 years ago

@blowdart

blowdart commented 6 years ago

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 commented 6 years ago

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

jeffschwMSFT commented 5 years ago

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

DamianEdwards commented 5 years ago

ping ?

jeffschwMSFT commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@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 commented 5 years ago

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 commented 4 years ago

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 commented 4 years ago

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

vitek-karas commented 4 years ago

agreed 😢

swaroop-sridhar commented 4 years ago

Me too.

swaroop-sridhar commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

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: https://github.com/dotnet/runtime/pull/644 and https://github.com/dotnet/runtime/pull/690

brianrob commented 4 years ago

Sounds good. Thanks much @swaroop-sridhar.

agocke commented 3 years ago

I believe this work has been completed in #690

vitek-karas commented 3 years ago

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.

dotnet / runtime

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

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.