## Proposed changes
For .NET Core 3 the proposal is to keep the existing behavior as described above and add two additional ways to capture the tracing:
-* Redirect the trace to a file instead - this would be done by setting `COREHOST_TRACE=1` and also `COREHOST_TRACEFILE=<path>` in the environment for the process.
+* Redirect the trace to a file (always appends) - this would be done by setting `COREHOST_TRACE=1` and also `COREHOST_TRACEFILE=<path>` in the environment for the process.
+* Add a knob to control trace verbosity `COREHOST_TRACE_VERBOSITY`. If unset tracing will be exhaustive. When set in the range 1-4 the tracing verbosity will increase with an increase in the value of `COREHOST_TRACE_VERBOSITY`.
+ * `COREHOST_TRACE_VERBOSITY=1 will show errors
+ * `COREHOST_TRACE_VERBOSITY=2 will show errors and warnings
+ * `COREHOST_TRACE_VERBOSITY=3 will show errors, warnings, and info
+ * `COREHOST_TRACE_VERBOSITY=4 will show errors, warnings, info, and verbose.
* For custom host support a way to capture the trace output in code. This will be done by adding `*_set_trace_listener` functions to `hostfxr` and `hostpolicy` which would let the custom host intercept all tracing.
This is directly related to #4455.
## New trace routing
The host components implement two routes for tracing:
* Tracing to `stderr` (this is the .NET Core 2.1 behavior). This default route is activated by setting the `COREHOST_TRACE=1` environment variable.
-* Tracing to a file (new in .NET Core 3). This route is activated by setting the `COREHOST_TRACE=1` and also providing the full path to the trace file in `COREHOST_TRACEFILE=<path>` environment variable. This overrides the `stderr` route, so if the file tracing is enabled, traces will not be written to `stderr`.
+* Tracing to a file (new in .NET Core 3). This route is activated by setting the `COREHOST_TRACE=1` and also providing the full path to the trace file in `COREHOST_TRACEFILE=<path>` environment variable. This overrides the `stderr` route, so if the file tracing is enabled, traces will not be written to `stderr`. Instead traces will be appended to the specified file.
Custom host can enable a third route which passes tracing into a registered trace listener. The custom host does this by implementating `host_trace_listener` interface and registering it through:
``` C++
## Future investments
### Trace content
Currently the host components tend to trace a lot. The trace contains lot of interesting information but it's done in a very verbose way which is sometimes hard to navigate. Future investment should look at the common scenarios which are using the host tracing and optimize the trace output for those scenarios. This doesn't necessarily mean decrease the amount of tracing, but possibly introduce "summary sections" which would describe the end result decisions for certain scenarios.
-It would also be good to review the usage of verbose versus info tracing and make it consistent. Possibly also add an environment variable (or similar) to control info/verbose tracing for the `stderr` and file based tracing. Currently all traces are written always.
+It would also be good to review the usage of verbose versus info tracing and make it consistent.
### Interaction with other diagnostics in the .NET Core
The host tracing covers several areas which are interesting for diagnosing common failure patterns:
* Resolving frameworks
* Resolving assemblies (and native libraries)
-Especially resolution of assemblies is tightly coupled with assembly binder behavior at runtime. As of now there's no correlation or cooperation between the host tracing and the runtime diagnostics (exceptions, logging) in the assembly binder. Future improvements might investigate ways to introduce some amount of cooperation to make the various diagnostic techniques easier to use together.
\ No newline at end of file
+Especially resolution of assemblies is tightly coupled with assembly binder behavior at runtime. As of now there's no correlation or cooperation between the host tracing and the runtime diagnostics (exceptions, logging) in the assembly binder. Future improvements might investigate ways to introduce some amount of cooperation to make the various diagnostic techniques easier to use together.
inline string_t exe_suffix() { return _X(".exe"); }
- pal::string_t to_string(int value);
-
- bool getcwd(pal::string_t* recv);
-
inline int cstrcasecmp(const char* str1, const char* str2) { return ::_stricmp(str1, str2); }
inline int strcmp(const char_t* str1, const char_t* str2) { return ::wcscmp(str1, str2); }
inline int strcasecmp(const char_t* str1, const char_t* str2) { return ::_wcsicmp(str1, str2); }
inline int strncmp(const char_t* str1, const char_t* str2, int len) { return ::wcsncmp(str1, str2, len); }
inline int strncasecmp(const char_t* str1, const char_t* str2, int len) { return ::_wcsnicmp(str1, str2, len); }
- pal::string_t to_lower(const pal::string_t& in);
-
inline size_t strlen(const char_t* str) { return ::wcslen(str); }
+ inline FILE * file_open(const pal::string_t& path, const char_t* mode) { return ::_wfopen(path.c_str(), mode); }
+ inline void file_vprintf(FILE* f, const char_t* format, va_list vl) { ::vfwprintf(f, format, vl); ::fputwc(_X('\n'), f); }
inline void err_vprintf(const char_t* format, va_list vl) { ::vfwprintf(stderr, format, vl); ::fputwc(_X('\n'), stderr); }
inline void out_vprintf(const char_t* format, va_list vl) { ::vfwprintf(stdout, format, vl); ::fputwc(_X('\n'), stdout); }
inline string_t exe_suffix() { return _X(""); }
- pal::string_t to_string(int value);
-
- bool getcwd(pal::string_t* recv);
-
inline int cstrcasecmp(const char* str1, const char* str2) { return ::strcasecmp(str1, str2); }
inline int strcmp(const char_t* str1, const char_t* str2) { return ::strcmp(str1, str2); }
inline int strcasecmp(const char_t* str1, const char_t* str2) { return ::strcasecmp(str1, str2); }
inline int strncmp(const char_t* str1, const char_t* str2, int len) { return ::strncmp(str1, str2, len); }
inline int strncasecmp(const char_t* str1, const char_t* str2, int len) { return ::strncasecmp(str1, str2, len); }
- pal::string_t to_lower(const pal::string_t& in);
-
inline size_t strlen(const char_t* str) { return ::strlen(str); }
+ inline FILE * file_open(const pal::string_t& path, const char_t* mode) { return fopen(path.c_str(), mode); }
+ inline void file_vprintf(FILE* f, const char_t* format, va_list vl) { ::vfprintf(f, format, vl); ::fputc('\n', f); }
inline void err_vprintf(const char_t* format, va_list vl) { ::vfprintf(stderr, format, vl); ::fputc('\n', stderr); }
inline void out_vprintf(const char_t* format, va_list vl) { ::vfprintf(stdout, format, vl); ::fputc('\n', stdout); }
inline bool pal_utf8string(const pal::string_t& str, std::vector<char>* out) { out->assign(str.begin(), str.end()); out->push_back('\0'); return true; }
#endif
+ pal::string_t to_string(int value);
+ pal::string_t get_timestamp();
+
+ bool getcwd(pal::string_t* recv);
+ pal::string_t to_lower(const pal::string_t& in);
+
+
+ inline void file_flush(FILE *f) { std::fflush(f); }
inline void err_flush() { std::fflush(stderr); }
inline void out_flush() { std::fflush(stdout); }
#include <unistd.h>
#include <fcntl.h>
#include <fnmatch.h>
+#include <ctime>
#if defined(__APPLE__)
#include <mach-o/dyld.h>
return ret;
}
+pal::string_t pal::get_timestamp()
+{
+ std::time_t t = std::time(0);
+ const std::size_t elems = 100;
+ char_t buf[elems];
+ std::strftime(buf, elems, _X("%c %Z"), std::gmtime(&t));
+
+ return pal::string_t(buf);
+}
+
bool pal::touch_file(const pal::string_t& path)
{
int fd = open(path.c_str(), (O_CREAT | O_EXCL), (S_IRUSR | S_IRGRP | S_IROTH));
#include <locale>
#include <codecvt>
#include <ShlObj.h>
+#include <ctime>
+
bool GetModuleFileNameWrapper(HMODULE hModule, pal::string_t* recv)
{
return std::to_wstring(value);
}
+pal::string_t pal::get_timestamp()
+{
+ std::time_t t = std::time(0);
+ const std::size_t elems = 100;
+ char_t buf[elems];
+ std::wcsftime(buf, elems, _X("%c %Z"), std::gmtime(&t));
+
+ return pal::string_t(buf);
+}
+
bool pal::touch_file(const pal::string_t& path)
{
HANDLE hnd = ::CreateFileW(path.c_str(), 0, 0, NULL, CREATE_NEW, FILE_ATTRIBUTE_NORMAL, NULL);
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
#include "trace.h"
+#include <mutex>
-static bool g_enabled = false;
+// g_trace_verbosity is used to encode COREHOST_TRACE and COREHOST_TRACE_VERBOSITY to selectively control output of
+// trace::warn(), trace::info(), and trace::verbose()
+// COREHOST_TRACE=0 COREHOST_TRACE_VERBOSITY=N/A implies g_trace_verbosity = 0. // Trace "disabled". error() messages will be produced.
+// COREHOST_TRACE=1 COREHOST_TRACE_VERBOSITY=4 or unset implies g_trace_verbosity = 4. // Trace "enabled". verbose(), info(), warn() and error() messages will be produced
+// COREHOST_TRACE=1 COREHOST_TRACE_VERBOSITY=3 implies g_trace_verbosity = 3. // Trace "enabled". info(), warn() and error() messages will be produced
+// COREHOST_TRACE=1 COREHOST_TRACE_VERBOSITY=2 implies g_trace_verbosity = 2. // Trace "enabled". warn() and error() messages will be produced
+// COREHOST_TRACE=1 COREHOST_TRACE_VERBOSITY=1 implies g_trace_verbosity = 1. // Trace "enabled". error() messages will be produced
+static int g_trace_verbosity = 0;
+static FILE * g_trace_file = stderr;
+static std::mutex g_trace_mutex;
//
-// Turn on tracing for the corehost based on "COREHOST_TRACE" env.
+// Turn on tracing for the corehost based on "COREHOST_TRACE" & "COREHOST_TRACEFILE" env.
//
void trace::setup()
{
auto trace_val = pal::xtoi(trace_str.c_str());
if (trace_val > 0)
{
- trace::enable();
- trace::info(_X("Tracing enabled"));
+ if (trace::enable())
+ {
+ auto ts = pal::get_timestamp();
+ trace::info(_X("Tracing enabled @ %s"), ts.c_str());
+ }
}
}
-void trace::enable()
+bool trace::enable()
{
- g_enabled = true;
+ bool file_open_error = false;
+ pal::string_t tracefile_str;
+
+ if (g_trace_verbosity)
+ {
+ return false;
+ }
+ else
+ {
+ std::lock_guard<std::mutex> lock(g_trace_mutex);
+
+ g_trace_file = stderr;
+ if (pal::getenv(_X("COREHOST_TRACEFILE"), &tracefile_str))
+ {
+ FILE *tracefile = pal::file_open(tracefile_str, _X("a"));
+
+ if (tracefile)
+ {
+ g_trace_file = tracefile;
+ }
+ else
+ {
+ file_open_error = true;
+ }
+ }
+
+ pal::string_t trace_str;
+ if (!pal::getenv(_X("COREHOST_TRACE_VERBOSITY"), &trace_str))
+ {
+ g_trace_verbosity = 4; // Verbose trace by default
+ }
+ else
+ {
+ g_trace_verbosity = pal::xtoi(trace_str.c_str());
+ }
+ }
+
+ if (file_open_error)
+ {
+ trace::error(_X("Unable to open COREHOST_TRACEFILE=%s for writing"), tracefile_str.c_str());
+ }
+ return true;
}
bool trace::is_enabled()
{
- return g_enabled;
+ return g_trace_verbosity;
}
void trace::verbose(const pal::char_t* format, ...)
{
- if (g_enabled)
+ if (g_trace_verbosity > 3)
{
+ std::lock_guard<std::mutex> lock(g_trace_mutex);
+
va_list args;
va_start(args, format);
- pal::err_vprintf(format, args);
+ pal::file_vprintf(g_trace_file, format, args);
va_end(args);
}
}
void trace::info(const pal::char_t* format, ...)
{
- if (g_enabled)
+ if (g_trace_verbosity > 2)
{
+ std::lock_guard<std::mutex> lock(g_trace_mutex);
+
va_list args;
va_start(args, format);
- pal::err_vprintf(format, args);
+ pal::file_vprintf(g_trace_file, format, args);
va_end(args);
}
}
void trace::error(const pal::char_t* format, ...)
{
+ std::lock_guard<std::mutex> lock(g_trace_mutex);
+
// Always print errors
va_list args;
va_start(args, format);
pal::err_vprintf(format, args);
+ if (g_trace_verbosity && (g_trace_file != stderr))
+ {
+ pal::file_vprintf(g_trace_file, format, args);
+ }
va_end(args);
}
void trace::println(const pal::char_t* format, ...)
{
+ std::lock_guard<std::mutex> lock(g_trace_mutex);
+
va_list args;
va_start(args, format);
pal::out_vprintf(format, args);
void trace::warning(const pal::char_t* format, ...)
{
- if (g_enabled)
+ if (g_trace_verbosity > 1)
{
+ std::lock_guard<std::mutex> lock(g_trace_mutex);
+
va_list args;
va_start(args, format);
- pal::err_vprintf(format, args);
+ pal::file_vprintf(g_trace_file, format, args);
va_end(args);
}
}
void trace::flush()
{
+ std::lock_guard<std::mutex> lock(g_trace_mutex);
+
+ pal::file_flush(g_trace_file);
pal::err_flush();
pal::out_flush();
-}
\ No newline at end of file
+}
namespace trace
{
void setup();
- void enable();
+ bool enable();
bool is_enabled();
void verbose(const pal::char_t* format, ...);
void info(const pal::char_t* format, ...);
--- /dev/null
+// Copyright (c) .NET Foundation and contributors. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+
+using System;
+using System.IO;
+using System.Linq;
+using Xunit;
+using Microsoft.Extensions.DependencyModel;
+
+namespace Microsoft.DotNet.CoreSetup.Test.HostActivation.Tracing
+{
+ public class GivenThatICareAboutTracing : IClassFixture<GivenThatICareAboutTracing.SharedTestState>
+ {
+ private SharedTestState sharedTestState;
+
+ // Trace messages currently expected for a passing app (somewhat randomly selected)
+ private const String ExpectedVerboseMessage = "--- Begin breadcrumb write";
+ private const String ExpectedInfoMessage = "Deps file:";
+ private const String ExpectedBadPathMessage = "Unable to open COREHOST_TRACEFILE=";
+
+ public GivenThatICareAboutTracing(GivenThatICareAboutTracing.SharedTestState fixture)
+ {
+ sharedTestState = fixture;
+ }
+
+ [Fact]
+ public void TracingOff()
+ {
+ var fixture = sharedTestState.PreviouslyPublishedAndRestoredPortableAppProjectFixture.Copy();
+ var dotnet = fixture.BuiltDotnet;
+ var appDll = fixture.TestProject.AppDll;
+
+ dotnet.Exec(appDll)
+ .CaptureStdOut()
+ .CaptureStdErr()
+ .Execute()
+ .Should()
+ .Pass()
+ .And
+ .NotHaveStdErrContaining(ExpectedInfoMessage)
+ .And
+ .NotHaveStdErrContaining(ExpectedVerboseMessage);
+ }
+
+ [Fact]
+ public void TracingOnDefault()
+ {
+ var fixture = sharedTestState.PreviouslyPublishedAndRestoredPortableAppProjectFixture.Copy();
+ var dotnet = fixture.BuiltDotnet;
+ var appDll = fixture.TestProject.AppDll;
+
+ dotnet.Exec(appDll)
+ .EnvironmentVariable("COREHOST_TRACE", "1")
+ .CaptureStdOut()
+ .CaptureStdErr()
+ .Execute()
+ .Should()
+ .Pass()
+ .And
+ .HaveStdOutContaining("Hello World")
+ .And
+ .HaveStdErrContaining(ExpectedInfoMessage)
+ .And
+ .HaveStdErrContaining(ExpectedVerboseMessage);
+ }
+
+ [Fact]
+ public void TracingOnVerbose()
+ {
+ var fixture = sharedTestState.PreviouslyPublishedAndRestoredPortableAppProjectFixture.Copy();
+ var dotnet = fixture.BuiltDotnet;
+ var appDll = fixture.TestProject.AppDll;
+
+ dotnet.Exec(appDll)
+ .EnvironmentVariable("COREHOST_TRACE", "1")
+ .EnvironmentVariable("COREHOST_TRACE_VERBOSITY", "4")
+ .CaptureStdOut()
+ .CaptureStdErr()
+ .Execute()
+ .Should()
+ .Pass()
+ .And
+ .HaveStdOutContaining("Hello World")
+ .And
+ .HaveStdErrContaining(ExpectedInfoMessage)
+ .And
+ .HaveStdErrContaining(ExpectedVerboseMessage);
+ }
+
+ [Fact]
+ public void TracingOnInfo()
+ {
+ var fixture = sharedTestState.PreviouslyPublishedAndRestoredPortableAppProjectFixture.Copy();
+ var dotnet = fixture.BuiltDotnet;
+ var appDll = fixture.TestProject.AppDll;
+
+ dotnet.Exec(appDll)
+ .EnvironmentVariable("COREHOST_TRACE", "1")
+ .EnvironmentVariable("COREHOST_TRACE_VERBOSITY", "3")
+ .CaptureStdOut()
+ .CaptureStdErr()
+ .Execute()
+ .Should()
+ .Pass()
+ .And
+ .HaveStdOutContaining("Hello World")
+ .And
+ .HaveStdErrContaining(ExpectedInfoMessage)
+ .And
+ .NotHaveStdErrContaining(ExpectedVerboseMessage);
+ }
+
+ [Fact]
+ public void TracingOnWarning()
+ {
+ var fixture = sharedTestState.PreviouslyPublishedAndRestoredPortableAppProjectFixture.Copy();
+ var dotnet = fixture.BuiltDotnet;
+ var appDll = fixture.TestProject.AppDll;
+
+ dotnet.Exec(appDll)
+ .EnvironmentVariable("COREHOST_TRACE", "1")
+ .EnvironmentVariable("COREHOST_TRACE_VERBOSITY", "2")
+ .CaptureStdOut()
+ .CaptureStdErr()
+ .Execute()
+ .Should()
+ .Pass()
+ .And
+ .HaveStdOutContaining("Hello World")
+ .And
+ .NotHaveStdErrContaining(ExpectedInfoMessage)
+ .And
+ .NotHaveStdErrContaining(ExpectedVerboseMessage);
+ }
+
+ [Fact]
+ public void TracingOnToFileDefault()
+ {
+ var fixture = sharedTestState.PreviouslyPublishedAndRestoredPortableAppProjectFixture.Copy();
+ var dotnet = fixture.BuiltDotnet;
+ var appDll = fixture.TestProject.AppDll;
+
+ dotnet.Exec(appDll)
+ .EnvironmentVariable("COREHOST_TRACE", "1")
+ .EnvironmentVariable("COREHOST_TRACEFILE", "TracingOnToFileDefault.log")
+ .CaptureStdOut()
+ .CaptureStdErr()
+ .Execute()
+ .Should()
+ .Pass()
+ .And
+ .HaveStdOutContaining("Hello World")
+ .And
+ .NotHaveStdErrContaining(ExpectedInfoMessage)
+ .And
+ .NotHaveStdErrContaining(ExpectedVerboseMessage)
+ .And
+ .FileExists("TracingOnToFileDefault.log")
+ .And
+ .FileContains("TracingOnToFileDefault.log", ExpectedVerboseMessage);
+ }
+
+ [Fact]
+ public void TracingOnToFileBadPathDefault()
+ {
+ var fixture = sharedTestState.PreviouslyPublishedAndRestoredPortableAppProjectFixture.Copy();
+ var dotnet = fixture.BuiltDotnet;
+ var appDll = fixture.TestProject.AppDll;
+
+ dotnet.Exec(appDll)
+ .EnvironmentVariable("COREHOST_TRACE", "1")
+ .EnvironmentVariable("COREHOST_TRACEFILE", "badpath/TracingOnToFileBadPathDefault.log")
+ .CaptureStdOut()
+ .CaptureStdErr()
+ .Execute()
+ .Should()
+ .Pass()
+ .And
+ .HaveStdOutContaining("Hello World")
+ .And
+ .HaveStdErrContaining(ExpectedInfoMessage)
+ .And
+ .HaveStdErrContaining(ExpectedVerboseMessage)
+ .And
+ .HaveStdErrContaining(ExpectedBadPathMessage);
+ }
+
+ public class SharedTestState : IDisposable
+ {
+ // Entry point projects
+ public TestProjectFixture PreviouslyPublishedAndRestoredPortableAppProjectFixture { get; set; }
+
+ public RepoDirectoriesProvider RepoDirectories { get; set; }
+
+ public SharedTestState()
+ {
+ RepoDirectories = new RepoDirectoriesProvider();
+
+ // Entry point projects
+ PreviouslyPublishedAndRestoredPortableAppProjectFixture = new TestProjectFixture("PortableApp", RepoDirectories)
+ .EnsureRestored(RepoDirectories.CorehostPackages)
+ .PublishProject();
+ }
+
+ public void Dispose()
+ {
+ // Entry point projects
+ PreviouslyPublishedAndRestoredPortableAppProjectFixture.Dispose();
+ }
+ }
+ }
+}
return new AndConstraint<CommandResultAssertions>(this);
}
+ public AndConstraint<CommandResultAssertions> FileExists(string path)
+ {
+ Execute.Assertion.ForCondition(System.IO.File.Exists(path))
+ .FailWith("The command did not write the expected file: {0}{1}", path, GetDiagnosticsInfo());
+ return new AndConstraint<CommandResultAssertions>(this);
+ }
+
+ public AndConstraint<CommandResultAssertions> FileContains(string path, string pattern)
+ {
+ Execute.Assertion.ForCondition(System.IO.File.ReadAllText(path).Contains(pattern))
+ .FailWith("The command did not write the expected result '{1}' to the file: {1}{2}", pattern, path, GetDiagnosticsInfo());
+ return new AndConstraint<CommandResultAssertions>(this);
+ }
+
+ public AndConstraint<CommandResultAssertions> NotFileContains(string path, string pattern)
+ {
+ Execute.Assertion.ForCondition(!System.IO.File.ReadAllText(path).Contains(pattern))
+ .FailWith("The command did not write the expected result '{1}' to the file: {1}{2}", pattern, path, GetDiagnosticsInfo());
+ return new AndConstraint<CommandResultAssertions>(this);
+ }
private string GetDiagnosticsInfo()
{
projects / platform / upstream / dotnet / runtime.git / commitdiff