From 68085acb27924bbc539dadc91943e98aa7c6a46e Mon Sep 17 00:00:00 2001 From: Mateusz Lach Date: Wed, 22 Mar 2023 15:41:22 +0100 Subject: [PATCH 1/2] sdk diagnostic listener eventlevel based on configured log level --- .../SdkSelfDiagnosticsEventListener.cs | 16 ++++++++-- .../Instrumentation.cs | 3 +- .../Logging/IOtelLogger.cs | 2 ++ .../Logging/InternalLogger.cs | 7 +++-- .../Logging/NoopLogger.cs | 2 ++ .../SdkSelfDiagnosticsEventListenerTests.cs | 30 +++++++++---------- 6 files changed, 38 insertions(+), 22 deletions(-) diff --git a/src/OpenTelemetry.AutoInstrumentation/Diagnostics/SdkSelfDiagnosticsEventListener.cs b/src/OpenTelemetry.AutoInstrumentation/Diagnostics/SdkSelfDiagnosticsEventListener.cs index e23402229a..b02590b6cf 100644 --- a/src/OpenTelemetry.AutoInstrumentation/Diagnostics/SdkSelfDiagnosticsEventListener.cs +++ b/src/OpenTelemetry.AutoInstrumentation/Diagnostics/SdkSelfDiagnosticsEventListener.cs @@ -34,10 +34,10 @@ internal class SdkSelfDiagnosticsEventListener : EventListener private readonly IOtelLogger log; private readonly List? eventSourcesBeforeConstructor = new(); - public SdkSelfDiagnosticsEventListener(EventLevel eventLevel, IOtelLogger logger) + public SdkSelfDiagnosticsEventListener(IOtelLogger logger) { log = logger; - logLevel = eventLevel; + logLevel = LogLevelToEventLevel(logger.Level); List? eventSources; lock (lockObj) @@ -120,4 +120,16 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData) break; } } + + private static EventLevel LogLevelToEventLevel(LogLevel loggerLevel) + { + return loggerLevel switch + { + LogLevel.Debug => EventLevel.Verbose, + LogLevel.Error => EventLevel.Error, + LogLevel.Warning => EventLevel.Warning, + LogLevel.Information => EventLevel.Informational, + _ => throw new ArgumentOutOfRangeException(nameof(loggerLevel), loggerLevel, null) + }; + } } diff --git a/src/OpenTelemetry.AutoInstrumentation/Instrumentation.cs b/src/OpenTelemetry.AutoInstrumentation/Instrumentation.cs index 957e43ba6c..db0ae84fa4 100644 --- a/src/OpenTelemetry.AutoInstrumentation/Instrumentation.cs +++ b/src/OpenTelemetry.AutoInstrumentation/Instrumentation.cs @@ -14,7 +14,6 @@ // limitations under the License. // -using System.Diagnostics.Tracing; using OpenTelemetry.AutoInstrumentation.Configurations; using OpenTelemetry.AutoInstrumentation.Diagnostics; using OpenTelemetry.AutoInstrumentation.Loading; @@ -115,7 +114,7 @@ public static void Initialize() if (TracerSettings.Value.TracesEnabled || MetricSettings.Value.MetricsEnabled) { // Initialize SdkSelfDiagnosticsEventListener to create an EventListener for the OpenTelemetry SDK - _sdkEventListener = new(EventLevel.Warning, Logger); + _sdkEventListener = new(Logger); // Register to shutdown events AppDomain.CurrentDomain.ProcessExit += OnExit; diff --git a/src/OpenTelemetry.AutoInstrumentation/Logging/IOtelLogger.cs b/src/OpenTelemetry.AutoInstrumentation/Logging/IOtelLogger.cs index bdb1d065fc..9fc79c31ef 100644 --- a/src/OpenTelemetry.AutoInstrumentation/Logging/IOtelLogger.cs +++ b/src/OpenTelemetry.AutoInstrumentation/Logging/IOtelLogger.cs @@ -18,6 +18,8 @@ namespace OpenTelemetry.AutoInstrumentation.Logging; internal interface IOtelLogger { + LogLevel Level { get; } + bool IsEnabled(LogLevel level); void Debug(string messageTemplate, bool writeToEventLog = true); diff --git a/src/OpenTelemetry.AutoInstrumentation/Logging/InternalLogger.cs b/src/OpenTelemetry.AutoInstrumentation/Logging/InternalLogger.cs index 1e728fef19..c380ed6806 100644 --- a/src/OpenTelemetry.AutoInstrumentation/Logging/InternalLogger.cs +++ b/src/OpenTelemetry.AutoInstrumentation/Logging/InternalLogger.cs @@ -21,17 +21,18 @@ internal class InternalLogger : IOtelLogger private static readonly object[] NoPropertyValues = Array.Empty(); private readonly ISink _sink; - private readonly LogLevel _logLevel; internal InternalLogger(ISink sink, LogLevel logLevel) { _sink = sink ?? throw new ArgumentNullException(nameof(sink)); - _logLevel = logLevel; + Level = logLevel; } + public LogLevel Level { get; } + public bool IsEnabled(LogLevel level) { - return level <= _logLevel; + return level <= Level; } public void Debug(string messageTemplate, bool writeToEventLog) diff --git a/src/OpenTelemetry.AutoInstrumentation/Logging/NoopLogger.cs b/src/OpenTelemetry.AutoInstrumentation/Logging/NoopLogger.cs index a225bd5ae2..08c552d172 100644 --- a/src/OpenTelemetry.AutoInstrumentation/Logging/NoopLogger.cs +++ b/src/OpenTelemetry.AutoInstrumentation/Logging/NoopLogger.cs @@ -27,6 +27,8 @@ private NoopLogger() { } + public LogLevel Level => default; + public bool IsEnabled(LogLevel level) { return false; diff --git a/test/OpenTelemetry.AutoInstrumentation.Tests/Diagnostics/SdkSelfDiagnosticsEventListenerTests.cs b/test/OpenTelemetry.AutoInstrumentation.Tests/Diagnostics/SdkSelfDiagnosticsEventListenerTests.cs index 299b42b228..2a640ba696 100644 --- a/test/OpenTelemetry.AutoInstrumentation.Tests/Diagnostics/SdkSelfDiagnosticsEventListenerTests.cs +++ b/test/OpenTelemetry.AutoInstrumentation.Tests/Diagnostics/SdkSelfDiagnosticsEventListenerTests.cs @@ -16,10 +16,8 @@ // Source originated from https://github.com/open-telemetry/opentelemetry-dotnet/blob/23609730ddd73c860553de847e67c9b2226cff94/test/OpenTelemetry.Tests/Internal/SelfDiagnosticsEventListenerTest.cs -using System.Collections.Generic; using System.Diagnostics.Tracing; -using FluentAssertions; -using FluentAssertions.Execution; +using Moq; using OpenTelemetry.AutoInstrumentation.Diagnostics; using OpenTelemetry.AutoInstrumentation.Logging; using Xunit; @@ -35,33 +33,35 @@ public class SdkSelfDiagnosticsEventListenerTests [Fact] public void EventSourceSetup_LowerSeverity() { - var testSink = new TestSink(); - var logger = new InternalLogger(testSink, LogLevel.Debug); - using var listener = new SdkSelfDiagnosticsEventListener(EventLevel.Error, logger); + var logger = new Mock(); + logger.Setup(otelLogger => otelLogger.Level).Returns(LogLevel.Error); + + using var listener = new SdkSelfDiagnosticsEventListener(logger.Object); // Emitting a Verbose event. Or any EventSource event with lower severity than Error. AspNetTelemetryEventSourceForTests.Log.ActivityRestored("123"); OpenTelemetrySdkEventSourceForTests.Log.ActivityStarted("Activity started", "1"); - testSink.Messages.Should().BeEmpty("events with lower severity than error should not be written."); + logger.Verify(otelLogger => otelLogger.Level, Times.Once); + logger.VerifyNoOtherCalls(); } [Fact] public void EventSourceSetup_HigherSeverity() { - var testSink = new TestSink(); - var logger = new InternalLogger(testSink, LogLevel.Debug); - using var listener = new SdkSelfDiagnosticsEventListener(EventLevel.Verbose, logger); + var logger = new Mock(); + logger.Setup(otelLogger => otelLogger.Level).Returns(LogLevel.Debug); + + using var listener = new SdkSelfDiagnosticsEventListener(logger.Object); // Emitting a Verbose event. Or any EventSource event with lower severity than Error. AspNetTelemetryEventSourceForTests.Log.ActivityRestored("123"); OpenTelemetrySdkEventSourceForTests.Log.ActivityStarted("Activity started", "1"); - using (new AssertionScope()) - { - testSink.Messages.Should().Contain(msg => msg.Contains("EventSource=OpenTelemetry-Instrumentation-AspNet-Telemetry-For-Tests, Message=Activity restored, Id='123'")); - testSink.Messages.Should().Contain(msg => msg.Contains("EventSource=OpenTelemetry-Sdk-For-Tests, Message=Activity started.")); - } + logger.Verify(otelLogger => otelLogger.Level, Times.Once); + logger.Verify(otelLogger => otelLogger.Information("EventSource={0}, Message={1}", "OpenTelemetry-Instrumentation-AspNet-Telemetry-For-Tests", "Activity restored, Id='123'", false), Times.Once); + logger.Verify(otelLogger => otelLogger.Debug("EventSource={0}, Message={1}", "OpenTelemetry-Sdk-For-Tests", "Activity started. OperationName = 'Activity started', Id = '1'.", false), Times.Once); + logger.VerifyNoOtherCalls(); } [EventSource(Name = "OpenTelemetry-Instrumentation-AspNet-Telemetry-For-Tests")] From 0d1a8b115e7fb55ea8a1f4365df5d8612160751a Mon Sep 17 00:00:00 2001 From: Mateusz Lach Date: Thu, 23 Mar 2023 10:30:32 +0100 Subject: [PATCH 2/2] remove mocks from tests --- .../SdkSelfDiagnosticsEventListenerTests.cs | 81 +++++++++++++------ 1 file changed, 55 insertions(+), 26 deletions(-) diff --git a/test/OpenTelemetry.AutoInstrumentation.Tests/Diagnostics/SdkSelfDiagnosticsEventListenerTests.cs b/test/OpenTelemetry.AutoInstrumentation.Tests/Diagnostics/SdkSelfDiagnosticsEventListenerTests.cs index 2a640ba696..ad8109872a 100644 --- a/test/OpenTelemetry.AutoInstrumentation.Tests/Diagnostics/SdkSelfDiagnosticsEventListenerTests.cs +++ b/test/OpenTelemetry.AutoInstrumentation.Tests/Diagnostics/SdkSelfDiagnosticsEventListenerTests.cs @@ -17,7 +17,8 @@ // Source originated from https://github.com/open-telemetry/opentelemetry-dotnet/blob/23609730ddd73c860553de847e67c9b2226cff94/test/OpenTelemetry.Tests/Internal/SelfDiagnosticsEventListenerTest.cs using System.Diagnostics.Tracing; -using Moq; +using FluentAssertions; +using FluentAssertions.Execution; using OpenTelemetry.AutoInstrumentation.Diagnostics; using OpenTelemetry.AutoInstrumentation.Logging; using Xunit; @@ -33,35 +34,45 @@ public class SdkSelfDiagnosticsEventListenerTests [Fact] public void EventSourceSetup_LowerSeverity() { - var logger = new Mock(); - logger.Setup(otelLogger => otelLogger.Level).Returns(LogLevel.Error); + var testSink = new TestSink(); + var logger = new InternalLogger(testSink, LogLevel.Error); + using var listener = new SdkSelfDiagnosticsEventListener(logger); - using var listener = new SdkSelfDiagnosticsEventListener(logger.Object); + AspNetTelemetryEventSourceForTests.Log.Information(); + AspNetTelemetryEventSourceForTests.Log.Warning(); + OpenTelemetrySdkEventSourceForTests.Log.Verbose(); - // Emitting a Verbose event. Or any EventSource event with lower severity than Error. - AspNetTelemetryEventSourceForTests.Log.ActivityRestored("123"); - OpenTelemetrySdkEventSourceForTests.Log.ActivityStarted("Activity started", "1"); + // Events with both Critical and Error EventLevel are logged as errors. + OpenTelemetrySdkEventSourceForTests.Log.Error(); + OpenTelemetrySdkEventSourceForTests.Log.Critical(); - logger.Verify(otelLogger => otelLogger.Level, Times.Once); - logger.VerifyNoOtherCalls(); + using (new AssertionScope()) + { + testSink.Messages.Count.Should().Be(2); + testSink.Messages.Should().OnlyContain(msg => msg.Contains("Error")); + } } [Fact] public void EventSourceSetup_HigherSeverity() { - var logger = new Mock(); - logger.Setup(otelLogger => otelLogger.Level).Returns(LogLevel.Debug); + var testSink = new TestSink(); + var logger = new InternalLogger(testSink, LogLevel.Debug); + using var listener = new SdkSelfDiagnosticsEventListener(logger); - using var listener = new SdkSelfDiagnosticsEventListener(logger.Object); + AspNetTelemetryEventSourceForTests.Log.Information(); + AspNetTelemetryEventSourceForTests.Log.Warning(); + OpenTelemetrySdkEventSourceForTests.Log.Verbose(); + OpenTelemetrySdkEventSourceForTests.Log.Error(); - // Emitting a Verbose event. Or any EventSource event with lower severity than Error. - AspNetTelemetryEventSourceForTests.Log.ActivityRestored("123"); - OpenTelemetrySdkEventSourceForTests.Log.ActivityStarted("Activity started", "1"); - - logger.Verify(otelLogger => otelLogger.Level, Times.Once); - logger.Verify(otelLogger => otelLogger.Information("EventSource={0}, Message={1}", "OpenTelemetry-Instrumentation-AspNet-Telemetry-For-Tests", "Activity restored, Id='123'", false), Times.Once); - logger.Verify(otelLogger => otelLogger.Debug("EventSource={0}, Message={1}", "OpenTelemetry-Sdk-For-Tests", "Activity started. OperationName = 'Activity started', Id = '1'.", false), Times.Once); - logger.VerifyNoOtherCalls(); + using (new AssertionScope()) + { + testSink.Messages.Count.Should().Be(4); + testSink.Messages.Should().Contain(msg => msg.Contains("Error")); + testSink.Messages.Should().Contain(msg => msg.Contains("Warning")); + testSink.Messages.Should().Contain(msg => msg.Contains("Information")); + testSink.Messages.Should().Contain(msg => msg.Contains("Debug")); + } } [EventSource(Name = "OpenTelemetry-Instrumentation-AspNet-Telemetry-For-Tests")] @@ -73,10 +84,16 @@ private AspNetTelemetryEventSourceForTests() { } - [Event(4, Message = "Activity restored, Id='{0}'", Level = EventLevel.Informational)] - public void ActivityRestored(string id) + [Event(4, Message = "Activity info.", Level = EventLevel.Informational)] + public void Information() + { + WriteEvent(4); + } + + [Event(5, Message = "Activity warning.", Level = EventLevel.Warning)] + public void Warning() { - WriteEvent(4, id); + WriteEvent(5); } } @@ -89,10 +106,22 @@ private OpenTelemetrySdkEventSourceForTests() { } - [Event(24, Message = "Activity started. OperationName = '{0}', Id = '{1}'.", Level = EventLevel.Verbose)] - public void ActivityStarted(string operationName, string id) + [Event(24, Message = "Activity verbose.", Level = EventLevel.Verbose)] + public void Verbose() + { + WriteEvent(24); + } + + [Event(25, Message = "Activity error.", Level = EventLevel.Error)] + public void Error() + { + WriteEvent(25); + } + + [Event(26, Message = "Activity critical.", Level = EventLevel.Critical)] + public void Critical() { - WriteEvent(24, operationName, id); + WriteEvent(26); } } }