Add console sink to the diagnostic logging (#3558)

* Add console logger sink

* cleanup

* remove container detection

* add unit tests

* add managed logs output tests

* update tests

* Update docs

* refactor CreateSink

* refactor LoggerImpl

* reset whitespace

* fix native logger

---------

Co-authored-by: Rajkumar Rangaraj <rajrang@microsoft.com>
Co-authored-by: Paulo Janotti <pjanotti@splunk.com>
This commit is contained in:
Rasmus Kuusmann 2024-08-15 00:26:43 +03:00 committed by GitHub
parent 4f7d8aaf08
commit 02799ad61c
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
19 changed files with 342 additions and 37 deletions

View File

@ -32,6 +32,8 @@ This component adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.h
- `OTEL_EXPORTER_OTLP_LOGS_PROTOCOL`.
- Support for air-gapped installations through `DOWNLOAD_DIR` or `LOCAL_PATH`
arguments to `otel-dotnet-auto-install.sh`.
- Added `OTEL_DOTNET_AUTO_LOGGER` to select preferred sink for AutoInstrumentation
diagnostic logs.
### Changed

View File

@ -58,6 +58,7 @@ However, if given setting supports it, then:
| `OTEL_DOTNET_AUTO_HOME` | Installation location. | | [Experimental](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/versioning-and-stability.md) |
| `OTEL_DOTNET_AUTO_EXCLUDE_PROCESSES` | Names of the executable files that the profiler cannot instrument. Supports multiple comma-separated values, for example: `ReservedProcess.exe,powershell.exe`. If unset, the profiler attaches to all processes by default. \[1\]\[2\] | | [Experimental](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/versioning-and-stability.md) |
| `OTEL_DOTNET_AUTO_FAIL_FAST_ENABLED` | Enables possibility to fail process when automatic instrumentation cannot be executed. It is designed for debugging purposes. It should not be used in production environment. \[1\] | `false` | [Experimental](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/versioning-and-stability.md) |
| `OTEL_DOTNET_AUTO_LOGGER` | AutoInstrumentation diagnostic logs sink. (supported values: `none`,`file`,`console`) | `file` | [Experimental](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/versioning-and-stability.md) |
| `OTEL_LOG_LEVEL` | SDK log level. (supported values: `none`,`error`,`warn`,`info`,`debug`) | `info` | [Stable](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/versioning-and-stability.md) |
\[1\] If `OTEL_DOTNET_AUTO_FAIL_FAST_ENABLED` is set to `true` then processes

View File

@ -16,6 +16,9 @@
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\NoopLogger.cs">
<Link>Logging\NoopLogger.cs</Link>
</Compile>
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\ConsoleSink.cs">
<Link>Logging\ConsoleSink.cs</Link>
</Compile>
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\FileSink.cs">
<Link>Logging\FileSink.cs</Link>
</Compile>
@ -43,6 +46,9 @@
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\LogLevel.cs">
<Link>Logging\LogLevel.cs</Link>
</Compile>
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\LogSink.cs">
<Link>Logging\LogSink.cs</Link>
</Compile>
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\NoopSink.cs">
<Link>Logging\NoopSink.cs</Link>
</Compile>

View File

@ -14,6 +14,9 @@ namespace environment {
// Sets logging level used by autoinstrumentation loggers
const WSTRING log_level = WStr("OTEL_LOG_LEVEL");
// Sets logger used by autoinstrumentation
const WSTRING log_sink = WStr("OTEL_DOTNET_AUTO_LOGGER");
// Sets max size of a single log file
const WSTRING max_log_file_size = WStr("OTEL_DOTNET_AUTO_LOG_FILE_SIZE");

View File

@ -12,6 +12,7 @@
#include "spdlog/sinks/null_sink.h"
#include "spdlog/sinks/rotating_file_sink.h"
#include "spdlog/sinks/stdout_sinks.h"
#ifndef _WIN32
typedef struct stat Stat;
@ -34,6 +35,7 @@ class LoggerImpl : public Singleton<LoggerImpl<TLoggerPolicy>>
private:
std::shared_ptr<spdlog::logger> m_fileout;
static std::string GetLogPath(const std::string& file_name_suffix);
static std::shared_ptr<spdlog::logger> CreateFileSink(std::string logger_name);
LoggerImpl();
~LoggerImpl();
@ -43,6 +45,10 @@ private:
static inline const WSTRING log_level_info = WStr("info");
static inline const WSTRING log_level_debug = WStr("debug");
static inline const WSTRING log_sink_none = WStr("none");
static inline const WSTRING log_sink_file = WStr("file");
static inline const WSTRING log_sink_console = WStr("console");
static inline const std::string logger_name = "Logger";
bool ShouldLog(spdlog::level::level_enum log_level);
@ -93,6 +99,38 @@ std::string LoggerImpl<TLoggerPolicy>::GetLogPath(const std::string& file_name_s
return path;
}
template <typename TLoggerPolicy>
std::shared_ptr<spdlog::logger> LoggerImpl<TLoggerPolicy>::CreateFileSink(std::string logger_name)
{
static auto current_process_name = ToString(GetCurrentProcessName());
static auto current_process_id = GetPID();
static auto current_process_without_extension =
current_process_name.substr(0, current_process_name.find_last_of("."));
static auto file_name_suffix =
std::to_string(current_process_id) + "-" + current_process_without_extension + "-Native";
// by default, use the same size as on managed side: 10MiB
static auto file_size = GetConfiguredSize(environment::max_log_file_size, 10485760);
static std::shared_ptr<spdlog::logger> fileout;
try
{
fileout = spdlog::rotating_logger_mt(logger_name, GetLogPath(file_name_suffix), file_size, 10);
}
catch (...)
{
// By writing into the stderr was changing the behavior in a CI scenario.
// There's not a good way to report errors when trying to create the log file.
// But we never should be changing the normal behavior of an app.
// std::cerr << "LoggerImpl Handler: Error creating native log file." << std::endl;
fileout = spdlog::null_logger_mt(logger_name);
}
return fileout;
}
template <typename TLoggerPolicy>
LoggerImpl<TLoggerPolicy>::LoggerImpl()
{
@ -131,28 +169,22 @@ LoggerImpl<TLoggerPolicy>::LoggerImpl()
spdlog::flush_every(std::chrono::seconds(3));
static auto current_process_name = ToString(GetCurrentProcessName());
static auto current_process_id = GetPID();
static auto current_process_without_extension =
current_process_name.substr(0, current_process_name.find_last_of("."));
static auto configured_log_sink = GetEnvironmentValue(environment::log_sink);
static auto file_name_suffix =
std::to_string(current_process_id) + "-" + current_process_without_extension + "-Native";
// by default, use the same size as on managed side: 10MiB
static auto file_size = GetConfiguredSize(environment::max_log_file_size, 10485760);
try
if (configured_log_sink == log_sink_none)
{
m_fileout = spdlog::rotating_logger_mt(logger_name, GetLogPath(file_name_suffix), file_size, 10);
}
catch (...)
{
// By writing into the stderr was changing the behavior in a CI scenario.
// There's not a good way to report errors when trying to create the log file.
// But we never should be changing the normal behavior of an app.
// std::cerr << "LoggerImpl Handler: Error creating native log file." << std::endl;
m_fileout = spdlog::null_logger_mt(logger_name);
return;
}
else if (configured_log_sink == log_sink_console)
{
m_fileout = spdlog::stdout_logger_mt(logger_name);
}
// Default to file sink
else
{
// Creates file sink, if file sink creation fails fallbacks to NoOp sink.
m_fileout = CreateFileSink(logger_name);
}
m_fileout->set_level(log_level);
@ -237,7 +269,7 @@ void LoggerImpl<TLoggerPolicy>::Error(const Args&... args)
}
template <typename TLoggerPolicy>
template< typename... Args>
template <typename... Args>
void LoggerImpl<TLoggerPolicy>::Critical(const Args&... args)
{
// to avoid possibly unnecessary LogToString conversion, check log level before calling underlying logger
@ -259,13 +291,12 @@ void LoggerImpl<TLoggerPolicy>::Flush()
m_fileout->flush();
}
template <typename TLoggerPolicy>
bool LoggerImpl<TLoggerPolicy>::IsDebugEnabled() const
{
return m_fileout->level() == spdlog::level::debug;
}
} // namespace shared
} // namespace trace
#endif // OTEL_CLR_PROFILER_LOGGER_IMPL_H_

View File

@ -16,6 +16,9 @@
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\NoopLogger.cs">
<Link>Logging\NoopLogger.cs</Link>
</Compile>
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\ConsoleSink.cs">
<Link>Logging\ConsoleSink.cs</Link>
</Compile>
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\FileSink.cs">
<Link>Logging\FileSink.cs</Link>
</Compile>
@ -43,6 +46,9 @@
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\LogLevel.cs">
<Link>Logging\LogLevel.cs</Link>
</Compile>
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\LogSink.cs">
<Link>Logging\LogSink.cs</Link>
</Compile>
<Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\NoopSink.cs">
<Link>Logging\NoopSink.cs</Link>
</Compile>

View File

@ -63,6 +63,12 @@ internal static class Constants
public const string Information = "info";
public const string Debug = "debug";
}
public static class Loggers
{
public const string File = "file";
public const string Console = "console";
}
}
public static class EnvironmentVariables

View File

@ -0,0 +1,19 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0
namespace OpenTelemetry.AutoInstrumentation.Logging;
internal class ConsoleSink : ISink
{
private readonly string _source;
public ConsoleSink(string source)
{
_source = source;
}
public void Write(string message)
{
Console.WriteLine($"[{_source}] {message}");
}
}

View File

@ -3,7 +3,7 @@
namespace OpenTelemetry.AutoInstrumentation.Logging;
internal interface IOtelLogger
internal interface IOtelLogger : IDisposable
{
LogLevel Level { get; }

View File

@ -142,6 +142,14 @@ internal class InternalLogger : IOtelLogger
public void Error(Exception exception, string messageTemplate, object[] args, bool writeToEventLog)
=> Write(LogLevel.Error, exception, messageTemplate, args, writeToEventLog);
public void Dispose()
{
if (_sink is IDisposable disposableSink)
{
disposableSink.Dispose();
}
}
private static void WriteEventSourceLog(LogLevel level, string message)
{
switch (level)

View File

@ -0,0 +1,25 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0
namespace OpenTelemetry.AutoInstrumentation.Logging;
/// <summary>
/// Specifies the target sink.
/// </summary>
internal enum LogSink
{
/// <summary>
/// File sink.
/// </summary>
File,
/// <summary>
/// Std out or Console sink.
/// </summary>
Console,
/// <summary>
/// No op sink or null sink.
/// </summary>
NoOp
}

View File

@ -180,4 +180,8 @@ internal class NoopLogger : IOtelLogger
public void Error(Exception exception, string messageTemplate, object[] args, bool writeToEventLog = true)
{
}
public void Dispose()
{
}
}

View File

@ -14,13 +14,15 @@ internal static class OtelLogging
private const string OtelDotnetAutoLogDirectory = "OTEL_DOTNET_AUTO_LOG_DIRECTORY";
private const string OtelLogLevel = "OTEL_LOG_LEVEL";
private const string OtelDotnetAutoLogFileSize = "OTEL_DOTNET_AUTO_LOG_FILE_SIZE";
private const string OtelDotnetAutoLogger = "OTEL_DOTNET_AUTO_LOGGER";
private const string NixDefaultDirectory = "/var/log/opentelemetry/dotnet";
private static readonly long FileSizeLimitBytes = GetConfiguredFileSizeLimitBytes();
private static readonly LogLevel? ConfiguredLogLevel = GetConfiguredLogLevel();
private static readonly ConcurrentDictionary<string, IOtelLogger> OtelLoggers = new();
private static LogLevel? _configuredLogLevel = GetConfiguredLogLevel();
private static LogSink _configuredLogSink = GetConfiguredLogSink();
/// <summary>
/// Returns Logger implementation.
/// </summary>
@ -41,6 +43,13 @@ internal static class OtelLogging
return OtelLoggers.GetOrAdd(suffix, CreateLogger);
}
// Helper method for testing
internal static void Reset()
{
_configuredLogLevel = GetConfiguredLogLevel();
_configuredLogSink = GetConfiguredLogSink();
}
internal static LogLevel? GetConfiguredLogLevel()
{
LogLevel? logLevel = LogLevel.Information;
@ -66,6 +75,31 @@ internal static class OtelLogging
return logLevel;
}
internal static LogSink GetConfiguredLogSink()
{
// Use File as a default sink
var logSink = LogSink.File;
try
{
var configuredValue = Environment.GetEnvironmentVariable(OtelDotnetAutoLogger) ?? string.Empty;
logSink = configuredValue switch
{
Constants.ConfigurationValues.Loggers.File => LogSink.File,
Constants.ConfigurationValues.Loggers.Console => LogSink.Console,
Constants.ConfigurationValues.None => LogSink.NoOp,
_ => logSink
};
}
catch (Exception)
{
// theoretically, can happen when process has no privileges to check env
}
return logSink;
}
internal static long GetConfiguredFileSizeLimitBytes()
{
const long defaultFileSizeLimitBytes = 10 * 1024 * 1024;
@ -89,13 +123,35 @@ internal static class OtelLogging
private static IOtelLogger CreateLogger(string suffix)
{
ISink? sink = null;
if (!ConfiguredLogLevel.HasValue)
if (!_configuredLogLevel.HasValue)
{
return NoopLogger.Instance;
}
var sink = CreateSink(suffix);
return new InternalLogger(sink, _configuredLogLevel.Value);
}
private static ISink CreateSink(string suffix)
{
// Uses ISink? here, sink creation can fail so we specify default fallback at the end.
var sink = _configuredLogSink switch
{
LogSink.NoOp => new NoopSink(),
LogSink.Console => new ConsoleSink(suffix),
LogSink.File => CreateFileSink(suffix),
// default to null, then default value is specified only at the end.
_ => null,
};
return sink ??
// Default to NoopSink
new NoopSink();
}
private static ISink? CreateFileSink(string suffix)
{
try
{
var logDirectory = GetLogDirectory();
@ -103,7 +159,8 @@ internal static class OtelLogging
{
var fileName = GetLogFileName(suffix);
var logPath = Path.Combine(logDirectory, fileName);
sink = new RollingFileSink(
return new RollingFileSink(
path: logPath,
fileSizeLimitBytes: FileSizeLimitBytes,
retainedFileCountLimit: 10,
@ -117,9 +174,8 @@ internal static class OtelLogging
// unable to configure logging to a file
}
sink ??= new NoopSink();
return new InternalLogger(sink, ConfiguredLogLevel.Value);
// Could not create file sink
return null;
}
private static string GetLogFileName(string suffix)

View File

@ -181,6 +181,10 @@ internal class TestLogger : IOtelLogger
{
}
public void Dispose()
{
}
internal class LogRecord
{
public LogRecord(LogLevel logLevel, string message, Exception? exception = null)

View File

@ -14,7 +14,7 @@ namespace OpenTelemetry.AutoInstrumentation.Tests.Configurations;
// use collection to indicate that tests should not be run
// in parallel
// see https://xunit.net/docs/running-tests-in-parallel
[Collection("EventEmittingTests")]
[Collection("Non-Parallel Collection")]
public class SettingsTests : IDisposable
{
public SettingsTests()

View File

@ -15,7 +15,7 @@ namespace OpenTelemetry.AutoInstrumentation.Tests.Diagnostics;
// use collection to indicate that tests should not be run
// in parallel
// see https://xunit.net/docs/running-tests-in-parallel
[Collection("EventEmittingTests")]
[Collection("Non-Parallel Collection")]
public class SdkSelfDiagnosticsEventListenerTests
{
[Fact]

View File

@ -3,20 +3,22 @@
using FluentAssertions;
using OpenTelemetry.AutoInstrumentation.Logging;
using OpenTelemetry.AutoInstrumentation.Tests.Util;
using Xunit;
namespace OpenTelemetry.AutoInstrumentation.Tests;
[Collection("Non-Parallel Collection")]
public class OtelLoggingTests : IDisposable
{
public OtelLoggingTests()
{
UnsetLogLevelEnvVar();
UnsetLoggingEnvVars();
}
public void Dispose()
{
UnsetLogLevelEnvVar();
UnsetLoggingEnvVars();
}
[Fact]
@ -74,9 +76,113 @@ public class OtelLoggingTests : IDisposable
OtelLogging.GetConfiguredLogLevel().Should().BeNull();
}
private static void UnsetLogLevelEnvVar()
[Fact]
public void WhenLogSinkIsNotConfigured_Then_DefaultIsUsed()
{
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", null);
OtelLogging.GetConfiguredLogSink().Should().Be(LogSink.File);
}
[Fact]
public void WhenInvalidLogSinkIsConfigured_Then_DefaultIsUsed()
{
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", "invalid");
OtelLogging.GetConfiguredLogSink().Should().Be(LogSink.File);
}
[Fact]
public void WhenValidLogSinkIsConfigured_Then_ItIsUsed()
{
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", "console");
OtelLogging.GetConfiguredLogSink().Should().Be(LogSink.Console);
}
[Fact]
public void WhenNoLogSinkIsConfigured_Then_NoOpSinkIsUsed()
{
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", "none");
OtelLogging.GetConfiguredLogSink().Should().Be(LogSink.NoOp);
}
[Fact]
public void WhenFileSinkIsUsed_Then_FileContentIsDetected()
{
Environment.SetEnvironmentVariable("OTEL_LOG_LEVEL", "debug");
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", "file");
var tempLogsDirectory = DirectoryHelpers.CreateTempDirectory();
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOG_DIRECTORY", tempLogsDirectory.FullName);
try
{
// Reset internal state
OtelLogging.Reset();
var logger = OtelLogging.GetLogger("FileUnitTests");
var logLine = "== Test Log Here ==";
logger.Debug(logLine, false);
logger.Dispose(); // Dispose the logger to release the file
var files = tempLogsDirectory.GetFiles();
files.Length.Should().Be(1);
var content = File.ReadAllText(files[0].FullName);
content.Should().Contain(logLine);
}
finally
{
tempLogsDirectory.Delete(true);
}
}
[Fact]
public void WhenConsoleSinkIsUsed_Then_ConsoleContentIsDetected()
{
Environment.SetEnvironmentVariable("OTEL_LOG_LEVEL", "debug");
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", "console");
var currentWritter = Console.Out;
using var ms = new MemoryStream();
using var tw = new StreamWriter(ms);
Console.SetOut(tw);
try
{
// Reset internal state
OtelLogging.Reset();
var logger = OtelLogging.GetLogger("ConsoleUnitTests");
var logLine = "== Test Log Here ==";
logger.Debug(logLine, false);
tw.Flush(); // Forces rows to be written
using TextReader reader = new StreamReader(ms);
ms.Position = 0; // reset reading position
var content = reader.ReadToEnd();
content.Should().Contain(logLine);
}
finally
{
Console.SetOut(currentWritter);
}
}
private static void UnsetLoggingEnvVars()
{
Environment.SetEnvironmentVariable("OTEL_LOG_LEVEL", null);
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOG_FILE_SIZE", null);
Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", null);
}
}

View File

@ -0,0 +1,17 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0
namespace OpenTelemetry.AutoInstrumentation.Tests.Util;
internal static class DirectoryHelpers
{
public static DirectoryInfo CreateTempDirectory()
{
#if NET7_0_OR_GREATER
return Directory.CreateTempSubdirectory("managed_logs");
#else
var tempDir = Path.Combine(Path.GetTempPath(), "managed_logs_" + Path.GetRandomFileName());
return Directory.CreateDirectory(tempDir);
#endif
}
}

View File

@ -0,0 +1,11 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0
using Xunit;
namespace OpenTelemetry.AutoInstrumentation.Tests.Util;
[CollectionDefinition("Non-Parallel Collection", DisableParallelization = true)]
public class NonParallelCollectionDefinition
{
}