Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Encode event and write to file in SelfDiagnosticsEventListener #2265

Merged
merged 2 commits into from
May 13, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -0,0 +1,89 @@
namespace Microsoft.ApplicationInsights.Extensibility.Implementation.Tracing.SelfDiagnostics
{
using System;
using System.Collections.Generic;
using System.Diagnostics.Tracing;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using Moq;

// SelfDiagnosticsEventListener should be moved from SelfDiagnosticsInternals to SelfDiagnostics.
// Pending on https://github.com/microsoft/ApplicationInsights-dotnet/pull/2262
// Here still using this old namespace to show less changes in git diff view.
using Microsoft.ApplicationInsights.Extensibility.Implementation.Tracing.SelfDiagnosticsInternals;

[TestClass]
class SelfDiagnosticsEventListenerTest
{
[TestMethod]
[ExpectedException(typeof(ArgumentException))]
public void SelfDiagnosticsEventListener_constructor_Invalid_Input()
{
// no configRefresher object
_ = new SelfDiagnosticsEventListener(EventLevel.Error, null);
}

[TestMethod]
public void SelfDiagnosticsEventListener_EventSourceSetup_LowerSeverity()
{
var fileHandlerMock = new Mock<MemoryMappedFileHandler>();
var listener = new SelfDiagnosticsEventListener(EventLevel.Error, fileHandlerMock.Object);

// Emitting a Verbose event. Or any EventSource event with lower severity than Error.
CoreEventSource.Log.OperationIsNullWarning();
fileHandlerMock.Verify(fileHandler => fileHandler.Write(It.IsAny<byte[]>(), It.IsAny<int>()), Times.Never());
}

[TestMethod]
public void SelfDiagnosticsEventListener_EventSourceSetup_HigherSeverity()
{
var fileHandlerMock = new Mock<MemoryMappedFileHandler>();
fileHandlerMock.Setup(fileHandler => fileHandler.Write(It.IsAny<byte[]>(), It.IsAny<int>()));
var listener = new SelfDiagnosticsEventListener(EventLevel.Error, fileHandlerMock.Object);

// Emitting an Error event. Or any EventSource event with higher than or equal to to Error severity.
CoreEventSource.Log.InvalidOperationToStopError();
fileHandlerMock.Verify(fileHandler => fileHandler.Write(It.IsAny<byte[]>(), It.IsAny<int>()));
}

[TestMethod]
public void SelfDiagnosticsEventListener_DateTimeGetBytes()
{
var fileHandlerMock = new Mock<MemoryMappedFileHandler>();
var listener = new SelfDiagnosticsEventListener(EventLevel.Error, fileHandlerMock.Object);

// Check DateTimeKind of Utc, Local, and Unspecified
DateTime[] datetimes = new DateTime[]
{
DateTime.SpecifyKind(DateTime.Parse("1996-12-01T14:02:31.1234567-08:00"), DateTimeKind.Utc),
DateTime.SpecifyKind(DateTime.Parse("1996-12-01T14:02:31.1234567-08:00"), DateTimeKind.Local),
DateTime.SpecifyKind(DateTime.Parse("1996-12-01T14:02:31.1234567-08:00"), DateTimeKind.Unspecified),
DateTime.UtcNow,
DateTime.Now,
};

// Expect to match output string from DateTime.ToString("O")
string[] expected = new string[datetimes.Length];
for (int i = 0; i < datetimes.Length; i++)
{
expected[i] = datetimes[i].ToString("O");
}

byte[] buffer = new byte[40 * datetimes.Length];
int pos = 0;

// Get string after DateTimeGetBytes() write into a buffer
string[] results = new string[datetimes.Length];
for (int i = 0; i < datetimes.Length; i++)
{
int len = listener.DateTimeGetBytes(datetimes[i], buffer, pos);
results[i] = Encoding.Default.GetString(buffer, pos, len);
pos += len;
}

Assert.AreEqual(expected, results);
}
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,10 @@
namespace Microsoft.ApplicationInsights.Extensibility.Implementation.Tracing.SelfDiagnostics
{
internal class MemoryMappedFileHandler
{
public void Write(byte[] buffer, int byteCount)
{
// TODO. Placeholder for SelfDiagnosticsEventListener
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -8,24 +8,35 @@
using System.Text;
using System.Threading;

// SelfDiagnosticsEventListener should be moved from SelfDiagnosticsInternals to SelfDiagnostics.
// Pending on https://github.com/microsoft/ApplicationInsights-dotnet/pull/2262
// Here still using this old namespace to show less changes in git diff view.
using Microsoft.ApplicationInsights.Extensibility.Implementation.Tracing.SelfDiagnostics;

/// <summary>
/// SelfDiagnosticsEventListener class enables the events from OpenTelemetry event sources
/// and write the events to a local file in a circular way.
/// </summary>
internal class SelfDiagnosticsEventListener : EventListener
{
private const string EventSourceNamePrefix = "Microsoft-ApplicationInsights-";

// 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 readonly ThreadLocal<byte[]> writeBuffer = new ThreadLocal<byte[]>(() => null);
private readonly object lockObj = new object();
private readonly EventLevel logLevel;

// private readonly SelfDiagnosticsConfigRefresher configRefresher;
private readonly MemoryMappedFileHandler fileHandler;
private readonly List<EventSource> eventSourcesBeforeConstructor = new List<EventSource>();

public SelfDiagnosticsEventListener(EventLevel logLevel/*, SelfDiagnosticsConfigRefresher configRefresher*/)
private bool disposedValue = false;

public SelfDiagnosticsEventListener(EventLevel logLevel, MemoryMappedFileHandler fileHandler)
{
this.logLevel = logLevel;

// this.configRefresher = configRefresher ?? throw new ArgumentNullException(nameof(configRefresher));
this.fileHandler = fileHandler ?? throw new ArgumentNullException(nameof(fileHandler));

List<EventSource> eventSources;
lock (this.lockObj)
Expand All @@ -44,9 +55,211 @@ public SelfDiagnosticsEventListener(EventLevel logLevel/*, SelfDiagnosticsConfig
}
}

/// <inheritdoc/>
public override void Dispose()
{
this.Dispose(true);
GC.SuppressFinalize(this);
}

/// <summary>
/// Encode a string into the designated position in a buffer of bytes, which will be written as log.
/// If isParameter is true, wrap "{}" around the string.
/// The buffer should not be filled to full, leaving at least one byte empty space to fill a '\n' later.
/// If the buffer cannot hold all characters, truncate the string and replace extra content with "...".
/// The buffer is not guaranteed to be filled until the last byte due to variable encoding length of UTF-8,
/// in order to prioritize speed over space.
/// </summary>
/// <param name="str">The string to be encoded.</param>
/// <param name="isParameter">Whether the string is a parameter. If true, "{}" will be wrapped around the string.</param>
/// <param name="buffer">The byte array to contain the resulting sequence of bytes.</param>
/// <param name="position">The position at which to start writing the resulting sequence of bytes.</param>
/// <returns>The position of the buffer after the last byte of the resulting sequence.</returns>
internal static int EncodeInBuffer(string str, bool isParameter, byte[] buffer, int position)
{
int charCount = str.Length;
int ellipses = isParameter ? "{...}\n".Length : "...\n".Length;

// Ensure there is space for "{...}\n" or "...\n".
if (buffer.Length - position - ellipses < 0)
{
return position;
}

int estimateOfCharacters = (buffer.Length - position - ellipses) / 2;

// Ensure the UTF-16 encoded string can fit in buffer UTF-8 encoding.
// And leave space for "{...}\n" or "...\n".
if (charCount > estimateOfCharacters)
{
charCount = estimateOfCharacters;
}

if (isParameter)
{
buffer[position++] = (byte)'{';
}

position += Encoding.UTF8.GetBytes(str, 0, charCount, buffer, position);
if (charCount != str.Length)
{
buffer[position++] = (byte)'.';
buffer[position++] = (byte)'.';
buffer[position++] = (byte)'.';
}

if (isParameter)
{
buffer[position++] = (byte)'}';
}

return position;
}

internal void WriteEvent(string eventMessage, ReadOnlyCollection<object> payload)
{
// TODO
try
{
var buffer = this.writeBuffer.Value;
if (buffer == null)
{
buffer = new byte[BUFFERSIZE];
this.writeBuffer.Value = buffer;
}

var pos = this.DateTimeGetBytes(DateTime.UtcNow, buffer, 0);
buffer[pos++] = (byte)':';
pos = EncodeInBuffer(eventMessage, false, buffer, pos);
if (payload != null)
{
// Not using foreach because it can cause allocations
for (int i = 0; i < payload.Count; ++i)
{
object obj = payload[i];
if (obj != null)
{
pos = EncodeInBuffer(obj.ToString(), true, buffer, pos);
}
else
{
pos = EncodeInBuffer("null", true, buffer, pos);
}
}
}

buffer[pos++] = (byte)'\n';
this.fileHandler.Write(buffer, pos - 0);
}
catch (Exception)
{
// Fail to allocate memory for buffer
// In this case, silently fail.
}
}

/// <summary>
/// Write the <c>datetime</c> formatted string into <c>bytes</c> byte-array starting at <c>byteIndex</c> position.
/// <para>
/// [DateTimeKind.Utc]
/// format: yyyy - MM - dd T HH : mm : ss . fffffff Z (i.e. 2020-12-09T10:20:50.4659412Z).
/// </para>
/// <para>
/// [DateTimeKind.Local]
/// format: yyyy - MM - dd T HH : mm : ss . fffffff +|- HH : mm (i.e. 2020-12-09T10:20:50.4659412-08:00).
/// </para>
/// <para>
/// [DateTimeKind.Unspecified]
/// format: yyyy - MM - dd T HH : mm : ss . fffffff (i.e. 2020-12-09T10:20:50.4659412).
/// </para>
/// </summary>
/// <remarks>
/// The bytes array must be large enough to write 27-33 charaters from the byteIndex starting position.
/// </remarks>
/// <param name="datetime">DateTime.</param>
/// <param name="bytes">Array of bytes to write.</param>
/// <param name="byteIndex">Starting index into bytes array.</param>
/// <returns>The number of bytes written.</returns>
internal int DateTimeGetBytes(DateTime datetime, byte[] bytes, int byteIndex)
{
int num;
int pos = byteIndex;

num = datetime.Year;
bytes[pos++] = (byte)('0' + ((num / 1000) % 10));
bytes[pos++] = (byte)('0' + ((num / 100) % 10));
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));

bytes[pos++] = (byte)'-';

num = datetime.Month;
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));

bytes[pos++] = (byte)'-';

num = datetime.Day;
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));

bytes[pos++] = (byte)'T';

num = datetime.Hour;
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));

bytes[pos++] = (byte)':';

num = datetime.Minute;
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));

bytes[pos++] = (byte)':';

num = datetime.Second;
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));

bytes[pos++] = (byte)'.';

num = (int)(Math.Round(datetime.TimeOfDay.TotalMilliseconds * 10000) % 10000000);
bytes[pos++] = (byte)('0' + ((num / 1000000) % 10));
bytes[pos++] = (byte)('0' + ((num / 100000) % 10));
bytes[pos++] = (byte)('0' + ((num / 10000) % 10));
bytes[pos++] = (byte)('0' + ((num / 1000) % 10));
bytes[pos++] = (byte)('0' + ((num / 100) % 10));
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));

switch (datetime.Kind)
{
case DateTimeKind.Utc:
bytes[pos++] = (byte)'Z';
break;

case DateTimeKind.Local:
TimeSpan ts = TimeZoneInfo.Local.GetUtcOffset(datetime);

bytes[pos++] = (byte)(ts.Hours >= 0 ? '+' : '-');

num = Math.Abs(ts.Hours);
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));

bytes[pos++] = (byte)':';

num = ts.Minutes;
bytes[pos++] = (byte)('0' + ((num / 10) % 10));
bytes[pos++] = (byte)('0' + (num % 10));
break;

case DateTimeKind.Unspecified:
default:
// Skip
break;
}

return pos - byteIndex;
}

protected override void OnEventSourceCreated(EventSource eventSource)
Expand Down Expand Up @@ -89,5 +302,23 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
this.WriteEvent(eventData.Message, eventData.Payload);
}

protected virtual void Dispose(bool disposing)
{
if (this.disposedValue)
{
return;
}

if (disposing)
{
this.writeBuffer.Dispose();
}

this.disposedValue = true;

// Should call base.Dispose(disposing) here, but EventListener doesn't have Dispose(bool).
base.Dispose();
}
}
}