open-telemetry
/
opentelemetry-dotnet
mirror of https://github.com/open-telemetry/opentelemetry-dotnet.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Fix bug of recording events of all severity levels in .NET Frameworks in SelfDiagnostics (#1690) 

* Fix bug in SelfDiagnostics

* Add unit tests.

* Remove outdated comment

* Use a dedicated lock object

* Add two more test cases which calls OpenTelemetrySdkEventSource.Log and expect the events to be captured/omitted by SelfDiagnosticsEventListener as configured

* Fix failure under Linux: Emit Error level events to avoid interference of Verbose events from other sources

* remove outdated comment

Co-authored-by: Cijo Thomas <cithomas@microsoft.com>
This commit is contained in:
xiang17 2021-01-21 10:29:48 -08:00 committed by GitHub
parent 97ed5f54d4
commit 02adc4cce0
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 130 additions and 10 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
src/OpenTelemetry/Internal/SelfDiagnosticsConfigRefresher.cs
View File

@ -36,7 +36,7 @@ namespace OpenTelemetry.Internal
{
private const int ConfigurationUpdatePeriodMilliSeconds = 10000;
private static readonly byte[] MessageOnNewFile = Encoding.UTF8.GetBytes("Successfully opened file.");
private static readonly byte[] MessageOnNewFile = Encoding.UTF8.GetBytes("Successfully opened file.\n");
private readonly CancellationTokenSource cancellationTokenSource;
private readonly Task worker;

44
src/OpenTelemetry/Internal/SelfDiagnosticsEventListener.cs
View File

@ -15,11 +15,11 @@
// </copyright>
using System;
using System.Collections.Generic;
using System.Collections.ObjectModel;
using System.Diagnostics.Tracing;
using System.Globalization;
using System.IO;
using System.Linq;
using System.Text;
using System.Threading;
@ -34,14 +34,32 @@ namespace OpenTelemetry.Internal
// Buffer size of the log line. A UTF-16 encoded character in C# can take up to 4 bytes if encoded in UTF-8.
private const int BUFFERSIZE = 4 * 5120;
private const string EventSourceNamePrefix = "OpenTelemetry-";
private readonly object lockObj = new object();
private readonly EventLevel logLevel;
private readonly SelfDiagnosticsConfigRefresher configRefresher;
private readonly ThreadLocal<byte[]> writeBuffer = new ThreadLocal<byte[]>(() => null);
private readonly List<EventSource> eventSourcesBeforeConstructor = new List<EventSource>();
public SelfDiagnosticsEventListener(EventLevel logLevel, SelfDiagnosticsConfigRefresher configRefresher)
{
this.logLevel = logLevel;
this.configRefresher = configRefresher ?? throw new ArgumentNullException(nameof(configRefresher));
List<EventSource> eventSources;
lock (this.lockObj)
{
eventSources = this.eventSourcesBeforeConstructor;
this.eventSourcesBeforeConstructor = null;
}
foreach (var eventSource in eventSources)
{
#if NET452
this.EnableEvents(eventSource, this.logLevel, (EventKeywords)(-1));
#else
this.EnableEvents(eventSource, this.logLevel, EventKeywords.All);
#endif
}
}
/// <summary>
@ -105,7 +123,7 @@ namespace OpenTelemetry.Internal
var buffer = this.writeBuffer.Value;
if (buffer == null)
{
buffer = new byte[BUFFERSIZE]; // TODO: handle OOM
buffer = new byte[BUFFERSIZE];
this.writeBuffer.Value = buffer;
}
@ -118,7 +136,7 @@ namespace OpenTelemetry.Internal
// Not using foreach because it can cause allocations
for (int i = 0; i < payload.Count; ++i)
{
object obj = payload.ElementAt(i);
object obj = payload[i];
if (obj != null)
{
pos = EncodeInBuffer(obj.ToString(), true, buffer, pos);
@ -148,7 +166,8 @@ namespace OpenTelemetry.Internal
}
catch (Exception)
{
// One concurrent condition: memory mapped file is disposed in other thread after TryGetLogStream() finishes.
// Fail to allocate memory for buffer, or
// A concurrent condition: memory mapped file is disposed in other thread after TryGetLogStream() finishes.
// In this case, silently fail.
}
}
@ -157,6 +176,22 @@ namespace OpenTelemetry.Internal
{
if (eventSource.Name.StartsWith(EventSourceNamePrefix, StringComparison.Ordinal))
{
// If there are EventSource classes already initialized as of now, this method would be called from
// the base class constructor before the first line of code in SelfDiagnosticsEventListener constructor.
// In this case logLevel is always its default value, "LogAlways".
// Thus we should save the event source and enable them later, when code runs in constructor.
if (this.eventSourcesBeforeConstructor != null)
{
lock (this.lockObj)
{
if (this.eventSourcesBeforeConstructor != null)
{
this.eventSourcesBeforeConstructor.Add(eventSource);
return;
}
}
}
#if NET452
this.EnableEvents(eventSource, this.logLevel, (EventKeywords)(-1));
#else
@ -175,7 +210,6 @@ namespace OpenTelemetry.Internal
/// <param name="eventData">Data of the EventSource event.</param>
protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
// TODO: retrieve the file stream object from configRefresher and write to it
this.WriteEvent(eventData.Message, eventData.Payload);
}
}

94
test/OpenTelemetry.Tests/Internal/SelfDiagnosticsEventListenerTest.cs
View File

@ -41,10 +41,37 @@ namespace OpenTelemetry.Internal.Tests
});
}
[Fact]
[Trait("Platform", "Any")]
public void SelfDiagnosticsEventListener_EventSourceSetup_LowerSeverity()
{
var configRefresherMock = new Mock<SelfDiagnosticsConfigRefresher>();
var listener = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresherMock.Object);
// Emitting a Verbose event. Or any EventSource event with lower severity than Error.
OpenTelemetrySdkEventSource.Log.ActivityStarted("Activity started", "1");
configRefresherMock.Verify(refresher => refresher.TryGetLogStream(It.IsAny<int>(), out It.Ref<Stream>.IsAny, out It.Ref<int>.IsAny), Times.Never());
}
[Fact]
[Trait("Platform", "Any")]
public void SelfDiagnosticsEventListener_EventSourceSetup_HigherSeverity()
{
var configRefresherMock = new Mock<SelfDiagnosticsConfigRefresher>();
configRefresherMock.Setup(configRefresher => configRefresher.TryGetLogStream(It.IsAny<int>(), out It.Ref<Stream>.IsAny, out It.Ref<int>.IsAny))
.Returns(true);
var listener = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresherMock.Object);
// Emitting an Error event. Or any EventSource event with higher than or equal to to Error severity.
OpenTelemetrySdkEventSource.Log.TracerProviderException("TestEvent", "Exception Details");
configRefresherMock.Verify(refresher => refresher.TryGetLogStream(It.IsAny<int>(), out It.Ref<Stream>.IsAny, out It.Ref<int>.IsAny));
}
[Fact]
[Trait("Platform", "Any")]
public void SelfDiagnosticsEventListener_WriteEvent()
{
// Arrange
var configRefresherMock = new Mock<SelfDiagnosticsConfigRefresher>();
var memoryMappedFile = MemoryMappedFile.CreateFromFile(LOGFILEPATH, FileMode.Create, null, 1024);
Stream stream = memoryMappedFile.CreateViewStream();
@ -55,13 +82,67 @@ namespace OpenTelemetry.Internal.Tests
configRefresherMock.Setup(configRefresher => configRefresher.TryGetLogStream(timestampPrefixLength + bytes.Length + 1, out stream, out availableByteCount))
.Returns(true);
var listener = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresherMock.Object);
// Act: call WriteEvent method directly
listener.WriteEvent(eventMessage, null);
// Assert
configRefresherMock.Verify(refresher => refresher.TryGetLogStream(timestampPrefixLength + bytes.Length + 1, out stream, out availableByteCount));
stream.Dispose();
memoryMappedFile.Dispose();
AssertFileOutput(LOGFILEPATH, eventMessage);
}
[Fact]
[Trait("Platform", "Any")]
public void SelfDiagnosticsEventListener_EmitEvent_OmitAsConfigured()
{
// Arrange
var configRefresherMock = new Mock<SelfDiagnosticsConfigRefresher>();
var memoryMappedFile = MemoryMappedFile.CreateFromFile(LOGFILEPATH, FileMode.Create, null, 1024);
Stream stream = memoryMappedFile.CreateViewStream();
configRefresherMock.Setup(configRefresher => configRefresher.TryGetLogStream(It.IsAny<int>(), out stream, out It.Ref<int>.IsAny))
.Returns(true);
var listener = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresherMock.Object);
// Act: emit an event with severity lower than configured
OpenTelemetrySdkEventSource.Log.ActivityStarted("ActivityStart", "123");
// Assert
configRefresherMock.Verify(refresher => refresher.TryGetLogStream(It.IsAny<int>(), out stream, out It.Ref<int>.IsAny), Times.Never());
stream.Dispose();
memoryMappedFile.Dispose();
using FileStream file = File.Open(LOGFILEPATH, FileMode.Open, FileAccess.Read, FileShare.ReadWrite | FileShare.Delete);
var buffer = new byte[256];
file.Read(buffer, 0, buffer.Length);
Assert.Equal('\0', (char)buffer[0]);
}
[Fact]
[Trait("Platform", "Any")]
public void SelfDiagnosticsEventListener_EmitEvent_CaptureAsConfigured()
{
// Arrange
var configRefresherMock = new Mock<SelfDiagnosticsConfigRefresher>();
var memoryMappedFile = MemoryMappedFile.CreateFromFile(LOGFILEPATH, FileMode.Create, null, 1024);
Stream stream = memoryMappedFile.CreateViewStream();
configRefresherMock.Setup(configRefresher => configRefresher.TryGetLogStream(It.IsAny<int>(), out stream, out It.Ref<int>.IsAny))
.Returns(true);
var listener = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresherMock.Object);
// Act: emit an event with severity equal to configured
OpenTelemetrySdkEventSource.Log.TracerProviderException("TestEvent", "Exception Details");
// Assert
configRefresherMock.Verify(refresher => refresher.TryGetLogStream(It.IsAny<int>(), out stream, out It.Ref<int>.IsAny));
stream.Dispose();
memoryMappedFile.Dispose();
var expectedLog = "Unknown error in TracerProvider '{0}': '{1}'.{TestEvent}{Exception Details}";
AssertFileOutput(LOGFILEPATH, expectedLog);
}
[Fact]
[Trait("Platform", "Any")]
public void SelfDiagnosticsEventListener_EncodeInBuffer_Empty()
@ -170,11 +251,16 @@ namespace OpenTelemetry.Internal.Tests
using FileStream file = File.Open(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite | FileShare.Delete);
var buffer = new byte[256];
file.Read(buffer, 0, buffer.Length);
string logMessage = Encoding.UTF8.GetString(buffer);
string logLine = Encoding.UTF8.GetString(buffer);
string logMessage = ParseLogMessage(logLine);
Assert.StartsWith(eventMessage, logMessage);
}
private static string ParseLogMessage(string logLine)
{
int timestampPrefixLength = "2020-08-14T20:33:24.4788109Z:".Length;
string parsedEventMessage = logMessage.Substring(timestampPrefixLength);
Assert.StartsWith(eventMessage, parsedEventMessage);
Assert.Matches(@"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{7}Z:", logMessage.Substring(0, timestampPrefixLength));
Assert.Matches(@"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{7}Z:", logLine.Substring(0, timestampPrefixLength));
return logLine.Substring(timestampPrefixLength);
}
private static void AssertBufferOutput(byte[] expected, byte[] buffer, int startPos, int endPos)