From 04bcfacfd75579dfa4d2046e65fccb5af62bc856 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Fri, 20 Dec 2024 13:54:26 -0800 Subject: [PATCH 1/3] Add a log pipeline which doesn't route through ILogger. --- .../Counters/TraceEventExtensions.cs | 2 +- .../Logs/EventLogsPipeline.cs | 256 +++++++++++------- .../Logs/ILogRecordLogger.cs | 23 ++ .../Logs/LogObject.cs | 32 ++- .../Logs/LogRecord.cs | 63 +++++ .../Logs/LogRecordException.cs | 56 ++++ .../Logs/LogRecordPayload.cs | 19 ++ .../Logs/LogRecordScopeContainer.cs | 33 +++ .../Logs/TraceEventExtensions.cs | 241 +++++++++++++++++ .../LogsPipelineUnitTests.cs | 136 ++++++++++ 10 files changed, 748 insertions(+), 113 deletions(-) create mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/ILogRecordLogger.cs create mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecord.cs create mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordException.cs create mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordPayload.cs create mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordScopeContainer.cs create mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/TraceEventExtensions.cs create mode 100644 src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/LogsPipelineUnitTests.cs 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; + } + } +} From e6aac546fe83cb4432c98ce33d7dde17ec309965 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 19 Feb 2025 13:21:51 -0800 Subject: [PATCH 2/3] Code review. --- .../Logs/LogRecordException.cs | 32 +------------------ .../Logs/LogValuesFormatter.cs | 3 -- 2 files changed, 1 insertion(+), 34 deletions(-) diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordException.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordException.cs index 2962637a75..72b5198b1b 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordException.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordException.cs @@ -3,12 +3,9 @@ #nullable enable -using System; -using System.Diagnostics; - namespace Microsoft.Diagnostics.Monitoring.EventPipe { - internal readonly struct LogRecordException : IEquatable + internal readonly record struct LogRecordException { public LogRecordException( string? exceptionType, @@ -25,32 +22,5 @@ public LogRecordException( 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/LogValuesFormatter.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogValuesFormatter.cs index 21b0a17a30..e00b8cd73e 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogValuesFormatter.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogValuesFormatter.cs @@ -13,9 +13,6 @@ //with monitor modifications. namespace Microsoft.Diagnostics.Monitoring.EventPipe { - /// - /// Formatter to convert the named format items like {NamedformatItem} to format. - /// internal class LogValuesFormatter { private const string NullValue = "(null)"; From af2bca85c2e20bcce1ea9baf10512cdcf26a4cec Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Fri, 21 Feb 2025 13:43:34 -0800 Subject: [PATCH 3/3] Code review. --- .../Logs/EventLogsPipeline.cs | 12 +- .../Logs/LogMessageJsonEventData.cs | 51 +++++ .../Logs/LogRecordFactory.cs | 211 ++++++++++++++++++ .../Logs/LogRecordPayload.cs | 19 -- .../Logs/TraceEventExtensions.cs | 203 +---------------- 5 files changed, 280 insertions(+), 216 deletions(-) create mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogMessageJsonEventData.cs create mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordFactory.cs delete mode 100644 src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordPayload.cs diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs index b5f15ecf02..bd24eeb7ad 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs @@ -108,18 +108,20 @@ protected override async Task OnEventSourceAvailable(EventPipeEventSource eventS if (_logger != null) { + LogRecordFactory logRecordFactory = new(); + eventSource.Dynamic.AddCallbackForProviderEvent(LoggingSourceConfiguration.MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) => { if (!activityIdToScope.TryGetValue(traceEvent.ActivityID, out LogScopeItem scopeItem)) { activityIdToScope.TryGetValue(traceEvent.RelatedActivityID, out scopeItem); } - traceEvent.GetLogRecordPayloadFromMessageJsonEvent(scopeItem, out LogRecordPayload payload); + traceEvent.GetLogMessageJsonEventData(out LogMessageJsonEventData eventData); - _logger.Log( - in payload.LogRecord, - payload.Attributes, - new(payload.Scopes)); + logRecordFactory.EmitLog( + _logger, + scopeItem, + in eventData); }); } else diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogMessageJsonEventData.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogMessageJsonEventData.cs new file mode 100644 index 0000000000..298d253654 --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogMessageJsonEventData.cs @@ -0,0 +1,51 @@ +// 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 Microsoft.Extensions.Logging; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + internal readonly struct LogMessageJsonEventData + { + public DateTime Timestamp { get; } + public LogLevel LogLevel { get; } + public string CategoryName { get; } + public int EventId { get; } + public string EventName { get; } + public string ExceptionJson { get; } + public string ArgumentsJson { get; } + public string FormattedMessage { get; } + public string? ActivityTraceId { get; } + public string? ActivitySpanId { get; } + public string? ActivityTraceFlags { get; } + + public LogMessageJsonEventData( + DateTime timestamp, + LogLevel logLevel, + string categoryName, + int eventId, + string eventName, + string exceptionJson, + string argumentsJson, + string formattedMessage, + string? activityTraceId, + string? activitySpanId, + string? activityTraceFlags) + { + Timestamp = timestamp; + LogLevel = logLevel; + CategoryName = categoryName; + EventId = eventId; + EventName = eventName; + ExceptionJson = exceptionJson; + ArgumentsJson = argumentsJson; + FormattedMessage = formattedMessage; + ActivityTraceId = activityTraceId; + ActivitySpanId = activitySpanId; + ActivityTraceFlags = activityTraceFlags; + } + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordFactory.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordFactory.cs new file mode 100644 index 0000000000..f9bf2a5440 --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordFactory.cs @@ -0,0 +1,211 @@ +// 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.Extensions.Logging; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + internal sealed class LogRecordFactory + { + private static readonly UTF8Encoding s_Utf8Encoding = new(encoderShouldEmitUTF8Identifier: false, throwOnInvalidBytes: true); + private LogObject[] _ScopeStorage = new LogObject[16]; + private byte[] _JsonStorage = new byte[8192]; + private KeyValuePair[] _AttributeStorage = new KeyValuePair[16]; + + public void EmitLog( + ILogRecordLogger logger, + EventLogsPipeline.LogScopeItem? scopesLeafNode, + in LogMessageJsonEventData eventData) + { + int scopeCount = 0; + if (scopesLeafNode != null) + { + ref LogObject[] scopes = ref _ScopeStorage; + + do + { + AddToArrayGrowingAsNeeded(ref scopes, scopesLeafNode.ScopedObject, ref scopeCount); + + scopesLeafNode = scopesLeafNode.Parent; + } + while (scopesLeafNode != null); + } + + int numberOfAttributes = ParseAttributesFromJson(eventData.ArgumentsJson, out string? messageTemplate); + ParseLogRecordExceptionFromJson(eventData.ExceptionJson, out LogRecordException exception); + + if (!string.IsNullOrEmpty(eventData.FormattedMessage) + && eventData.FormattedMessage.Equals(messageTemplate)) + { + messageTemplate = null; + } + + LogRecord LogRecord = new( + eventData.Timestamp, + eventData.CategoryName, + eventData.LogLevel, + new EventId(eventData.EventId, eventData.EventName), + in exception, + eventData.FormattedMessage, + messageTemplate, + eventData.ActivityTraceId == null ? default : ActivityTraceId.CreateFromString(eventData.ActivityTraceId), + eventData.ActivitySpanId == null ? default : ActivitySpanId.CreateFromString(eventData.ActivitySpanId), + eventData.ActivityTraceFlags == "1" + ? ActivityTraceFlags.Recorded + : ActivityTraceFlags.None); + + ReadOnlySpan> Attributes = new(_AttributeStorage, 0, numberOfAttributes); + + ReadOnlySpan Scopes = new(_ScopeStorage, 0, scopeCount); + + logger.Log( + in LogRecord, + Attributes, + new(Scopes)); + } + + 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 int ParseAttributesFromJson(string argumentsJson, out string? messageTemplate) + { + messageTemplate = null; + + if (argumentsJson == "{}") + { + return 0; + } + + ref KeyValuePair[] attributes = ref _AttributeStorage; + + 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 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 Memory ParseJson(string json) + { + ref byte[] utf8 = ref _JsonStorage; + + 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/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordPayload.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordPayload.cs deleted file mode 100644 index 7418ba6eeb..0000000000 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/LogRecordPayload.cs +++ /dev/null @@ -1,19 +0,0 @@ -// 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/TraceEventExtensions.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/TraceEventExtensions.cs index d5f9b403af..0397e842d2 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/TraceEventExtensions.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/TraceEventExtensions.cs @@ -3,12 +3,7 @@ #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; @@ -16,18 +11,9 @@ 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( + public static void GetLogMessageJsonEventData( this TraceEvent traceEvent, - EventLogsPipeline.LogScopeItem? scopesLeafNode, - out LogRecordPayload payload) + out LogMessageJsonEventData eventData) { Debug.Assert(traceEvent.EventName == "MessageJson"); @@ -57,185 +43,18 @@ public static void GetLogRecordPayloadFromMessageJsonEvent( 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( + eventData = new( traceEvent.TimeStamp, - categoryName, logLevel, - new EventId(eventId, eventName), - in exception, + categoryName, + eventId, + eventName, + exceptionJson, + argsJson, 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); - } + activityTraceId, + activitySpanId, + activityTraceFlags); } } }