diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Counters/TraceEventExtensions.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Counters/TraceEventExtensions.cs index d6833da307..4b170a68dd 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Counters/TraceEventExtensions.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Counters/TraceEventExtensions.cs @@ -34,7 +34,7 @@ public CounterConfiguration(CounterFilter filter) internal record struct ProviderAndCounter(string ProviderName, string CounterName); - internal static class TraceEventExtensions + internal static partial class TraceEventExtensions { private static Dictionary counterMetadataByName = new(); private static Dictionary counterMetadataById = new(); diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs index 0b6f0824f6..b5f15ecf02 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs @@ -15,20 +15,30 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe internal class EventLogsPipeline : EventSourcePipeline { private readonly ILoggerFactory _factory; + private readonly ILogRecordLogger _logger; private static readonly Func _messageFormatter = MessageFormatter; + public EventLogsPipeline(DiagnosticsClient client, EventLogsPipelineSettings settings, ILoggerFactory factory) : base(client, settings) { _factory = factory ?? throw new ArgumentNullException(nameof(factory)); } + public EventLogsPipeline(DiagnosticsClient client, EventLogsPipelineSettings settings, ILogRecordLogger logger) + : base(client, settings) + { + _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + } + protected override MonitoringSourceConfiguration CreateConfiguration() { try { return new LoggingSourceConfiguration( Settings.LogLevel, - LogMessageType.FormattedMessage | LogMessageType.JsonMessage, + _logger == null + ? LogMessageType.FormattedMessage | LogMessageType.JsonMessage + : LogMessageType.JsonMessage, Settings.FilterSpecs, Settings.UseAppFilters, Settings.CollectScopes); @@ -39,9 +49,12 @@ protected override MonitoringSourceConfiguration CreateConfiguration() } } - protected override Task OnEventSourceAvailable(EventPipeEventSource eventSource, Func stopSessionAsync, CancellationToken token) + protected override async Task OnEventSourceAvailable(EventPipeEventSource eventSource, Func stopSessionAsync, CancellationToken token) { - string lastFormattedMessage = string.Empty; + if (_logger != null) + { + await _logger.PipelineStarted(token).ConfigureAwait(false); + } // // We enable TplEventSource's TasksFlowActivityIds as part of our configuration to enable activity correlation. @@ -93,122 +106,155 @@ protected override Task OnEventSourceAvailable(EventPipeEventSource eventSource, }); } - eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) => { - // Level, FactoryID, LoggerName, EventID, EventName, ExceptionJson, ArgumentsJson - LogLevel logLevel = (LogLevel)traceEvent.PayloadByName("Level"); - int factoryId = (int)traceEvent.PayloadByName("FactoryID"); - string categoryName = (string)traceEvent.PayloadByName("LoggerName"); - int eventId = (int)traceEvent.PayloadByName("EventId"); - string eventName = (string)traceEvent.PayloadByName("EventName"); - string exceptionJson = (string)traceEvent.PayloadByName("ExceptionJson"); - string argsJson = (string)traceEvent.PayloadByName("ArgumentsJson"); - - // There's a bug that causes some of the columns to get mixed up - if (eventName.StartsWith("{")) - { - argsJson = exceptionJson; - exceptionJson = eventName; - eventName = null; - } - - if (string.IsNullOrEmpty(argsJson)) - { - return; - } - - Exception exception = null; - - ILogger logger = _factory.CreateLogger(categoryName); - List scopes = new(); - - // - // The MessageJson event will occur with an ActivityId equal to the most relevant activity branch and we can backtrack to the root of the tree - // to grab all applicable scopes (where each node we visit is an applicable scope). - // - // Ideally the ActivityId will always exist in our tree, however if another trace is ongoing that is interested in an event start - // within the same async context as our log message then there will be nodes+edges that our tree is unaware of. - // This is because TplEventSource's TasksFlowActivityIds is a singleton implementation that is shared for all traces, - // regardless of if the other traces have TasksFlowActivityIds enabled. - // - // In this scenario there's still a chance that only a single branch has occurred and we're the first event logged with the newly branched ActivityId. - // In which case we can use the RelatedActivityId to find our way back onto the tree. - // - // If not then we will be operating on a subtree without a way of getting back to the root node and will only have a subset (if any) of the - // applicable scopes. - // - if (activityIdToScope.TryGetValue(traceEvent.ActivityID, out LogScopeItem scopeItem) || - activityIdToScope.TryGetValue(traceEvent.RelatedActivityID, out scopeItem)) - { - while (scopeItem != null) + if (_logger != null) + { + eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) => { + if (!activityIdToScope.TryGetValue(traceEvent.ActivityID, out LogScopeItem scopeItem)) { - scopes.Add(logger.BeginScope(scopeItem.ScopedObject)); + activityIdToScope.TryGetValue(traceEvent.RelatedActivityID, out scopeItem); + } + + traceEvent.GetLogRecordPayloadFromMessageJsonEvent(scopeItem, out LogRecordPayload payload); - scopeItem = scopeItem.Parent; + _logger.Log( + in payload.LogRecord, + payload.Attributes, + new(payload.Scopes)); + }); + } + else + { + string lastFormattedMessage = string.Empty; + + eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) => { + // Level, FactoryID, LoggerName, EventID, EventName, ExceptionJson, ArgumentsJson + LogLevel logLevel = (LogLevel)traceEvent.PayloadByName("Level"); + int factoryId = (int)traceEvent.PayloadByName("FactoryID"); + string categoryName = (string)traceEvent.PayloadByName("LoggerName"); + int eventId = (int)traceEvent.PayloadByName("EventId"); + string eventName = (string)traceEvent.PayloadByName("EventName"); + string exceptionJson = (string)traceEvent.PayloadByName("ExceptionJson"); + string argsJson = (string)traceEvent.PayloadByName("ArgumentsJson"); + + // There's a bug that causes some of the columns to get mixed up + if (eventName.StartsWith("{")) + { + argsJson = exceptionJson; + exceptionJson = eventName; + eventName = null; } - } - try - { - if (exceptionJson != "{}") + if (string.IsNullOrEmpty(argsJson)) { - JsonElement exceptionMessage = JsonSerializer.Deserialize(exceptionJson); - exception = new LoggerException(exceptionMessage); + return; } - JsonElement message = JsonSerializer.Deserialize(argsJson); - if (message.TryGetProperty("{OriginalFormat}", out JsonElement formatElement)) + Exception exception = null; + + ILogger logger = _factory.CreateLogger(categoryName); + List scopes = new(); + + // + // The MessageJson event will occur with an ActivityId equal to the most relevant activity branch and we can backtrack to the root of the tree + // to grab all applicable scopes (where each node we visit is an applicable scope). + // + // Ideally the ActivityId will always exist in our tree, however if another trace is ongoing that is interested in an event start + // within the same async context as our log message then there will be nodes+edges that our tree is unaware of. + // This is because TplEventSource's TasksFlowActivityIds is a singleton implementation that is shared for all traces, + // regardless of if the other traces have TasksFlowActivityIds enabled. + // + // In this scenario there's still a chance that only a single branch has occurred and we're the first event logged with the newly branched ActivityId. + // In which case we can use the RelatedActivityId to find our way back onto the tree. + // + // If not then we will be operating on a subtree without a way of getting back to the root node and will only have a subset (if any) of the + // applicable scopes. + // + if (activityIdToScope.TryGetValue(traceEvent.ActivityID, out LogScopeItem scopeItem) || + activityIdToScope.TryGetValue(traceEvent.RelatedActivityID, out scopeItem)) { - string formatString = formatElement.GetString(); - LogValuesFormatter formatter = new(formatString); - object[] args = new object[formatter.ValueNames.Count]; - for (int i = 0; i < args.Length; i++) + while (scopeItem != null) { - if (message.TryGetProperty(formatter.ValueNames[i], out JsonElement value)) + scopes.Add(logger.BeginScope(scopeItem.ScopedObject)); + + scopeItem = scopeItem.Parent; + } + } + + try + { + if (exceptionJson != "{}") + { + JsonElement exceptionMessage = JsonSerializer.Deserialize(exceptionJson); + exception = new LoggerException(exceptionMessage); + } + + JsonElement message = JsonSerializer.Deserialize(argsJson); + if (message.TryGetProperty("{OriginalFormat}", out JsonElement formatElement)) + { + string formatString = formatElement.GetString(); + LogValuesFormatter formatter = new(formatString); + object[] args = new object[formatter.ValueNames.Count]; + for (int i = 0; i < args.Length; i++) { - args[i] = value.GetString(); + if (message.TryGetProperty(formatter.ValueNames[i], out JsonElement value)) + { + args[i] = value.GetString(); + } } - } - //We want to propagate the timestamp to the underlying logger, but that's not part of the ILogger interface. - //We replicate LoggerExtensions.Log, but add an interface capability to the object - //CONSIDER FormattedLogValues maintains a cache of formatters. We are effectively duplicating this cache. - FormattedLogValues logValues = new(traceEvent.TimeStamp, formatString, args); - logger.Log(logLevel, new EventId(eventId, eventName), logValues, exception, _messageFormatter); + //We want to propagate the timestamp to the underlying logger, but that's not part of the ILogger interface. + //We replicate LoggerExtensions.Log, but add an interface capability to the object + //CONSIDER FormattedLogValues maintains a cache of formatters. We are effectively duplicating this cache. + FormattedLogValues logValues = new(traceEvent.TimeStamp, formatString, args); + logger.Log(logLevel, new EventId(eventId, eventName), logValues, exception, _messageFormatter); + } + else + { + LogObject obj = new(message, lastFormattedMessage) { Timestamp = traceEvent.TimeStamp }; + logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback); + } + } + catch (Exception) + { + } + finally + { + scopes.ForEach(d => d.Dispose()); } - else + }); + + eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "FormattedMessage", (traceEvent) => { + // Level, FactoryID, LoggerName, EventID, EventName, FormattedMessage + LogLevel logLevel = (LogLevel)traceEvent.PayloadByName("Level"); + int factoryId = (int)traceEvent.PayloadByName("FactoryID"); + string categoryName = (string)traceEvent.PayloadByName("LoggerName"); + int eventId = (int)traceEvent.PayloadByName("EventId"); + string eventName = (string)traceEvent.PayloadByName("EventName"); + string formattedMessage = (string)traceEvent.PayloadByName("FormattedMessage"); + + if (string.IsNullOrEmpty(formattedMessage)) { - LogObject obj = new(message, lastFormattedMessage) { Timestamp = traceEvent.TimeStamp }; - logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback); + formattedMessage = eventName; + eventName = string.Empty; } - } - catch (Exception) - { - } - finally - { - scopes.ForEach(d => d.Dispose()); - } - }); - - eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "FormattedMessage", (traceEvent) => { - // Level, FactoryID, LoggerName, EventID, EventName, FormattedMessage - LogLevel logLevel = (LogLevel)traceEvent.PayloadByName("Level"); - int factoryId = (int)traceEvent.PayloadByName("FactoryID"); - string categoryName = (string)traceEvent.PayloadByName("LoggerName"); - int eventId = (int)traceEvent.PayloadByName("EventId"); - string eventName = (string)traceEvent.PayloadByName("EventName"); - string formattedMessage = (string)traceEvent.PayloadByName("FormattedMessage"); - - if (string.IsNullOrEmpty(formattedMessage)) - { - formattedMessage = eventName; - eventName = string.Empty; - } - - lastFormattedMessage = formattedMessage; - }); - - return Task.CompletedTask; + + lastFormattedMessage = formattedMessage; + }); + + } + + if (_logger != null) + { + using EventTaskSource sourceCompletedTaskSource = new( + taskComplete => taskComplete, + handler => eventSource.Completed += handler, + handler => eventSource.Completed -= handler, + token); + + await sourceCompletedTaskSource.Task.ConfigureAwait(false); + + await _logger.PipelineStopped(token).ConfigureAwait(false); + } } private static string MessageFormatter(object state, Exception error) @@ -216,7 +262,7 @@ private static string MessageFormatter(object state, Exception error) return state.ToString(); } - private class LogScopeItem + internal class LogScopeItem { public Guid ActivityID { get; set; } diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/ILogRecordLogger.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/ILogRecordLogger.cs new file mode 100644 index 0000000000..a38f3362c1 --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/ILogRecordLogger.cs @@ -0,0 +1,23 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#nullable enable + +using System.Threading.Tasks; +using System.Threading; +using System.Collections.Generic; +using System; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + internal interface ILogRecordLogger + { + void Log( + in LogRecord log, + ReadOnlySpan> attributes, + in LogRecordScopeContainer scopes); + + Task PipelineStarted(CancellationToken token); + Task PipelineStopped(CancellationToken token); + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogObject.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogObject.cs index 804ad9df3e..c694598b2a 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogObject.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogObject.cs @@ -5,6 +5,8 @@ using System.Collections; using System.Collections.Generic; using System.Text.Json; +using System.Runtime.InteropServices; +using System.Buffers; namespace Microsoft.Diagnostics.Monitoring.EventPipe { @@ -13,12 +15,21 @@ public class LogObject : IReadOnlyList>, IStateWith public static readonly Func Callback = (state, exception) => ((LogObject)state).ToString(); private readonly string _formattedMessage; - private List> _items = new(); + private KeyValuePair[] _items = new KeyValuePair[8]; public LogObject(JsonElement element, string formattedMessage = null) { + int index = 0; + foreach (JsonProperty item in element.EnumerateObject()) { + if (index >= _items.Length) + { + KeyValuePair[] newArray = new KeyValuePair[_items.Length * 2]; + _items.CopyTo(newArray, 0); + _items = newArray; + } + switch (item.Value.ValueKind) { case JsonValueKind.Undefined: @@ -28,17 +39,17 @@ public LogObject(JsonElement element, string formattedMessage = null) case JsonValueKind.Array: break; case JsonValueKind.String: - _items.Add(new KeyValuePair(item.Name, item.Value.GetString())); + _items[index++] = new KeyValuePair(item.Name, item.Value.GetString()); break; case JsonValueKind.Number: - _items.Add(new KeyValuePair(item.Name, item.Value.GetInt32())); + _items[index++] = new KeyValuePair(item.Name, item.Value.GetInt32()); break; case JsonValueKind.False: case JsonValueKind.True: - _items.Add(new KeyValuePair(item.Name, item.Value.GetBoolean())); + _items[index++] = new KeyValuePair(item.Name, item.Value.GetBoolean()); break; case JsonValueKind.Null: - _items.Add(new KeyValuePair(item.Name, null)); + _items[index++] = new KeyValuePair(item.Name, null); break; default: break; @@ -46,17 +57,24 @@ public LogObject(JsonElement element, string formattedMessage = null) } _formattedMessage = formattedMessage; + Count = index; } public KeyValuePair this[int index] => _items[index]; - public int Count => _items.Count; + public int Count { get; private set; } public DateTime Timestamp { get; internal set; } + internal ReadOnlySpan> ToSpan() + => new(_items, 0, Count); + public IEnumerator> GetEnumerator() { - return _items.GetEnumerator(); + for (int i = 0; i < Count; i++) + { + yield return this[i]; + } } IEnumerator IEnumerable.GetEnumerator() diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecord.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecord.cs new file mode 100644 index 0000000000..122125f0bf --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecord.cs @@ -0,0 +1,63 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#nullable enable + +using System; +using System.Diagnostics; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + internal readonly struct LogRecord + { + public LogRecord( + DateTime timestamp, + string categoryName, + LogLevel logLevel, + EventId eventId, + in LogRecordException exception, + string? formattedMessage, + string? messageTemplate, + ActivityTraceId traceId, + ActivitySpanId spanId, + ActivityTraceFlags traceFlags) + { + if (string.IsNullOrEmpty(categoryName)) + { + throw new ArgumentNullException(nameof(categoryName)); + } + + Timestamp = timestamp; + CategoryName = categoryName; + LogLevel = logLevel; + EventId = eventId; + Exception = exception; + FormattedMessage = formattedMessage; + MessageTemplate = messageTemplate; + TraceId = traceId; + SpanId = spanId; + TraceFlags = traceFlags; + } + + public readonly DateTime Timestamp; + + public readonly string CategoryName; + + public readonly LogLevel LogLevel; + + public readonly EventId EventId; + + public readonly LogRecordException Exception; + + public readonly string? FormattedMessage; + + public readonly string? MessageTemplate; + + public readonly ActivityTraceId TraceId; + + public readonly ActivitySpanId SpanId; + + public readonly ActivityTraceFlags TraceFlags; + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordException.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordException.cs new file mode 100644 index 0000000000..2962637a75 --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordException.cs @@ -0,0 +1,56 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#nullable enable + +using System; +using System.Diagnostics; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + internal readonly struct LogRecordException : IEquatable + { + public LogRecordException( + string? exceptionType, + string? message, + string? stackTrace) + { + ExceptionType = exceptionType; + Message = message; + StackTrace = stackTrace; + } + + public readonly string? ExceptionType; + + public readonly string? Message; + + public readonly string? StackTrace; + + public bool Equals(LogRecordException other) + { + return ExceptionType == other.ExceptionType + && Message == other.Message + && StackTrace == other.StackTrace; + } + + public override bool Equals(object obj) + => obj is LogRecordException ex && Equals(ex); + + public override int GetHashCode() + { + HashCode hash = default; + + hash.Add(ExceptionType); + hash.Add(Message); + hash.Add(StackTrace); + + return hash.ToHashCode(); + } + + public static bool operator ==(LogRecordException left, LogRecordException right) + => left.Equals(right); + + public static bool operator !=(LogRecordException left, LogRecordException right) + => !left.Equals(right); + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordPayload.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordPayload.cs new file mode 100644 index 0000000000..7418ba6eeb --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordPayload.cs @@ -0,0 +1,19 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#nullable enable + +using System; +using System.Collections.Generic; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + internal ref struct LogRecordPayload + { + public LogRecord LogRecord; + + public ReadOnlySpan> Attributes; + + public ReadOnlySpan Scopes; + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordScopeContainer.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordScopeContainer.cs new file mode 100644 index 0000000000..55dc3bd912 --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordScopeContainer.cs @@ -0,0 +1,33 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#nullable enable + +using System.Collections.Generic; +using System; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + internal readonly ref struct LogRecordScopeContainer + { + private readonly ReadOnlySpan _Scopes; + + public LogRecordScopeContainer( + ReadOnlySpan scopes) + { + _Scopes = scopes; + } + + public void ForEachScope(LogRecordScopeAction callback, ref T state) + { + foreach (LogObject scope in _Scopes) + { + callback(scope.ToSpan(), ref state); + } + } + + public delegate void LogRecordScopeAction( + ReadOnlySpan> attributes, + ref T state); + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/TraceEventExtensions.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/TraceEventExtensions.cs new file mode 100644 index 0000000000..d5f9b403af --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/TraceEventExtensions.cs @@ -0,0 +1,241 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#nullable enable + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Diagnostics.CodeAnalysis; +using System.Text; +using System.Text.Json; +using Microsoft.Diagnostics.Tracing; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + internal static partial class TraceEventExtensions + { + private static readonly UTF8Encoding s_Utf8Encoding = new(encoderShouldEmitUTF8Identifier: false, throwOnInvalidBytes: true); + [ThreadStatic] + private static LogObject[]? s_ScopeStorage; + [ThreadStatic] + private static byte[]? s_JsonStorage; + [ThreadStatic] + private static KeyValuePair[]? s_AttributeStorage; + + public static void GetLogRecordPayloadFromMessageJsonEvent( + this TraceEvent traceEvent, + EventLogsPipeline.LogScopeItem? scopesLeafNode, + out LogRecordPayload payload) + { + Debug.Assert(traceEvent.EventName == "MessageJson"); + + LogLevel logLevel = (LogLevel)traceEvent.PayloadValue(0); + // int factoryId = (int)traceEvent.PayloadValue(1); + string categoryName = (string)traceEvent.PayloadValue(2); + int eventId = (int)traceEvent.PayloadValue(3); + string eventName = (string)traceEvent.PayloadValue(4); + string exceptionJson = (string)traceEvent.PayloadValue(5); + string argsJson = (string)traceEvent.PayloadValue(6); + string formattedMessage = (string)traceEvent.PayloadValue(7); + + string? activityTraceId; + string? activitySpanId; + string? activityTraceFlags; + if (traceEvent.Version >= 2) + { + // Note: Trace correlation fields added in .NET 9 + activityTraceId = (string)traceEvent.PayloadValue(8); + activitySpanId = (string)traceEvent.PayloadValue(9); + activityTraceFlags = (string)traceEvent.PayloadValue(10); + } + else + { + activityTraceId = null; + activitySpanId = null; + activityTraceFlags = null; + } + + int scopeCount = 0; + if (scopesLeafNode != null) + { + ref LogObject[]? scopes = ref s_ScopeStorage; + scopes ??= new LogObject[16]; + + do + { + AddToArrayGrowingAsNeeded(ref scopes, scopesLeafNode.ScopedObject, ref scopeCount); + + scopesLeafNode = scopesLeafNode.Parent; + } + while (scopesLeafNode != null); + } + + int numberOfAttributes = ParseAttributesFromJson(argsJson, out string? messageTemplate); + ParseLogRecordExceptionFromJson(exceptionJson, out LogRecordException exception); + + if (!string.IsNullOrEmpty(formattedMessage) + && formattedMessage.Equals(messageTemplate)) + { + messageTemplate = null; + } + + payload.LogRecord = new LogRecord( + traceEvent.TimeStamp, + categoryName, + logLevel, + new EventId(eventId, eventName), + in exception, + formattedMessage, + messageTemplate, + activityTraceId == null ? default : ActivityTraceId.CreateFromString(activityTraceId), + activitySpanId == null ? default : ActivitySpanId.CreateFromString(activitySpanId), + activityTraceFlags == "1" + ? ActivityTraceFlags.Recorded + : ActivityTraceFlags.None); + + payload.Attributes = new(s_AttributeStorage, 0, numberOfAttributes); + + payload.Scopes = new(s_ScopeStorage, 0, scopeCount); + } + + private static void AddToArrayGrowingAsNeeded(ref T[] destination, T item, ref int index) + { + if (index >= destination.Length) + { + T[] newArray = new T[destination.Length * 2]; + Array.Copy(destination, newArray, destination.Length); + destination = newArray; + } + + destination[index++] = item; + } + + private static int ParseAttributesFromJson(string argumentsJson, out string? messageTemplate) + { + messageTemplate = null; + + if (argumentsJson == "{}") + { + return 0; + } + + ref KeyValuePair[]? attributes = ref s_AttributeStorage; + attributes ??= new KeyValuePair[16]; + + Memory jsonBytes = ParseJson(argumentsJson); + + Utf8JsonReader reader = new(jsonBytes.Span); + + int attributeCount = 0; + while (reader.Read()) + { + if (reader.TokenType == JsonTokenType.PropertyName) + { + if (messageTemplate == null && reader.ValueTextEquals("{OriginalFormat}")) + { + if (!TryReadPropertyValue(ref reader, out messageTemplate)) + { + break; + } + } + else + { + string key = reader.GetString()!; + + if (!reader.Read() || reader.TokenType != JsonTokenType.String) + { + break; + } + + string value = reader.GetString()!; + + AddToArrayGrowingAsNeeded(ref attributes, new(key, value), ref attributeCount); + } + } + } + + return attributeCount; + } + + private static void ParseLogRecordExceptionFromJson(string exceptionJson, out LogRecordException exception) + { + if (exceptionJson == "{}") + { + exception = default; + return; + } + + Memory jsonBytes = ParseJson(exceptionJson); + + Utf8JsonReader reader = new(jsonBytes.Span); + + string? exceptionType = null; + string? message = null; + string? stackTrace = null; + + while (reader.Read()) + { + if (reader.TokenType == JsonTokenType.PropertyName) + { + if (reader.ValueTextEquals("TypeName")) + { + if (TryReadPropertyValue(ref reader, out exceptionType)) + { + continue; + } + } + else if (reader.ValueTextEquals("Message")) + { + if (TryReadPropertyValue(ref reader, out message)) + { + continue; + } + } + else if (reader.ValueTextEquals("VerboseMessage")) + { + if (TryReadPropertyValue(ref reader, out stackTrace)) + { + continue; + } + } + } + + break; + } + + exception = new(exceptionType, message, stackTrace); + } + + private static bool TryReadPropertyValue(ref Utf8JsonReader reader, [NotNullWhen(true)] out string? propertyValue) + { + if (reader.Read() && reader.TokenType == JsonTokenType.String) + { + propertyValue = reader.GetString()!; + return true; + } + + propertyValue = null; + return false; + } + + private static Memory ParseJson(string json) + { + ref byte[]? utf8 = ref s_JsonStorage; + utf8 ??= new byte[8192]; + + while (true) + { + int actualBytes = s_Utf8Encoding.GetBytes(json, utf8); + if (actualBytes < 0) + { + utf8 = new byte[utf8.Length * 2]; + continue; + } + + return new(utf8, 0, actualBytes); + } + } + } +} diff --git a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/LogsPipelineUnitTests.cs b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/LogsPipelineUnitTests.cs new file mode 100644 index 0000000000..0b11d899be --- /dev/null +++ b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/LogsPipelineUnitTests.cs @@ -0,0 +1,136 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#nullable enable + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Diagnostics.NETCore.Client; +using Microsoft.Diagnostics.TestHelpers; +using Microsoft.Extensions.Logging; +using Xunit; +using Xunit.Abstractions; +using Xunit.Extensions; +using TestRunner = Microsoft.Diagnostics.CommonTestRunner.TestRunner; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests +{ + public class LogsPipelineUnitTests + { + private const string LoggerRemoteTestName = "LoggerRemoteTest"; + + private readonly ITestOutputHelper _output; + + public static IEnumerable Configurations => TestRunner.Configurations; + + public LogsPipelineUnitTests(ITestOutputHelper output) + { + _output = output; + } + + [SkippableTheory, MemberData(nameof(Configurations))] + public async Task TestLogsPipeline(TestConfiguration config) + { + // TODO: When distributed tracing support lands EventPipeTracee + // gains the ability to start traces. When there is an active trace + // on .NET9+ logs should automatically receive correlation + // information (TraceId, SpanId, etc.). Expand this test to validate + // that once the ActivitySource modifications are present in + // EventPipeTracee. + + TestLogRecordLogger logger = new(); + + await using (TestRunner testRunner = await PipelineTestUtilities.StartProcess(config, LoggerRemoteTestName, _output)) + { + DiagnosticsClient client = new(testRunner.Pid); + + await using EventLogsPipeline pipeline = new( + client, + new EventLogsPipelineSettings + { + Duration = Timeout.InfiniteTimeSpan, + FilterSpecs = new Dictionary() + { + { LoggerRemoteTestName, LogLevel.Information } + } + }, + logger); + + await PipelineTestUtilities.ExecutePipelineWithTracee( + pipeline, + testRunner); + } + + Assert.Equal(5, logger.LogRecords.Count); + + var logRecordData = logger.LogRecords[0]; + + Assert.Equal("Some warning message with 6", logRecordData.LogRecord.FormattedMessage); + Assert.Equal("Some warning message with {Arg}", logRecordData.LogRecord.MessageTemplate); + Assert.Equal(LoggerRemoteTestName, logRecordData.LogRecord.CategoryName); + Assert.Equal(LogLevel.Information, logRecordData.LogRecord.LogLevel); + Assert.Equal(0, logRecordData.LogRecord.EventId.Id); + Assert.Single(logRecordData.Attributes); + Assert.Equal(new("Arg", "6"), logRecordData.Attributes[0]); + Assert.Single(logRecordData.Scopes); + Assert.Equal(new("IntValue", "5"), logRecordData.Scopes[0][0]); + Assert.Equal(new("BoolValue", "true"), logRecordData.Scopes[0][1]); + Assert.Equal(new("StringValue", "test"), logRecordData.Scopes[0][2]); + + logRecordData = logger.LogRecords[1]; + + Assert.Equal("Some other message with 7", logRecordData.LogRecord.FormattedMessage); + Assert.Equal("Some other message with {Arg}", logRecordData.LogRecord.MessageTemplate); + Assert.Equal(LoggerRemoteTestName, logRecordData.LogRecord.CategoryName); + Assert.Equal(LogLevel.Information, logRecordData.LogRecord.LogLevel); + Assert.Equal(0, logRecordData.LogRecord.EventId.Id); + Assert.Single(logRecordData.Attributes); + Assert.Equal(new("Arg", "7"), logRecordData.Attributes[0]); + Assert.Single(logRecordData.Scopes); + Assert.Equal(new("IntValue", "6"), logRecordData.Scopes[0][0]); + Assert.Equal(new("BoolValue", "false"), logRecordData.Scopes[0][1]); + Assert.Equal(new("StringValue", "string"), logRecordData.Scopes[0][2]); + + logRecordData = logger.LogRecords[2]; + + Assert.Equal("Another message", logRecordData.LogRecord.FormattedMessage); + Assert.Null(logRecordData.LogRecord.MessageTemplate); + Assert.Equal(LoggerRemoteTestName, logRecordData.LogRecord.CategoryName); + Assert.Equal(LogLevel.Warning, logRecordData.LogRecord.LogLevel); + Assert.Equal(7, logRecordData.LogRecord.EventId.Id); + Assert.Equal("AnotherEventId", logRecordData.LogRecord.EventId.Name); + Assert.Empty(logRecordData.Attributes); + Assert.Empty(logRecordData.Scopes); + } + + private sealed class TestLogRecordLogger : ILogRecordLogger + { + public List<(LogRecord LogRecord, KeyValuePair[] Attributes, List[]> Scopes)> LogRecords { get; } = new(); + + public void Log( + in LogRecord log, + ReadOnlySpan> attributes, + in LogRecordScopeContainer scopes) + { + List[]> scopeCopy = new(); + + scopes.ForEachScope(ScopeCallback, ref scopeCopy); + + LogRecords.Add((log, attributes.ToArray(), scopeCopy)); + + static void ScopeCallback(ReadOnlySpan> attributes, ref List[]> state) + { + state.Add(attributes.ToArray()); + } + } + + public Task PipelineStarted(CancellationToken token) => Task.CompletedTask; + + public Task PipelineStopped(CancellationToken token) => Task.CompletedTask; + } + } +}