From: Justin Anderson Date: Wed, 12 May 2021 22:25:16 +0000 (-0700) Subject: Add FilterSpecs to EventLogsPipeline (#2274) X-Git-Tag: submit/tizen/20210909.063632~15^2~34 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=7544afa43d28b4ddb76dfc5c613a4a50ccf0ee38;p=platform%2Fcore%2Fdotnet%2Fdiagnostics.git Add FilterSpecs to EventLogsPipeline (#2274) * Add FilterSpecs to EventLogsPipeline. * Set default value of UseAppFilters to true. * Add unit tests for all settings on EventLogsPipelineSettings. --- diff --git a/eng/Versions.props b/eng/Versions.props index 808c4f00a..52182fc96 100644 --- a/eng/Versions.props +++ b/eng/Versions.props @@ -41,8 +41,8 @@ 1.7.0 2.0.64 2.1.1 - - 3.1.4 + + 5.0.1 2.0.0-beta1.20468.1 2.0.0-beta1.20074.1 4.5.4 diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Configuration/LogMessageType.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Configuration/LogMessageType.cs new file mode 100644 index 000000000..aaf248d4b --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Configuration/LogMessageType.cs @@ -0,0 +1,16 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; + +namespace Microsoft.Diagnostics.Monitoring.EventPipe +{ + [Flags] + public enum LogMessageType + { + Message = 0x2, + FormattedMessage = 0x4, + JsonMessage = 0x8 + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Configuration/LoggingSourceConfiguration.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Configuration/LoggingSourceConfiguration.cs index 3b7ed790a..3cd63d20f 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Configuration/LoggingSourceConfiguration.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Configuration/LoggingSourceConfiguration.cs @@ -5,6 +5,7 @@ using System; using System.Collections.Generic; using System.Diagnostics.Tracing; +using System.Text; using Microsoft.Diagnostics.NETCore.Client; using Microsoft.Extensions.Logging; @@ -12,44 +13,111 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe { public class LoggingSourceConfiguration : MonitoringSourceConfiguration { - private const string UseAppFilters = "UseAppFilters"; - - private readonly LogLevel _level; - private readonly bool _useAppFilters; + private readonly string _filterSpecs; + private readonly long _keywords; + private readonly EventLevel _level; /// /// Creates a new logging source configuration. /// - /// The logging level. Log messages at or above the log level will be included. - /// Use the UseAppFilters filterspec. This supersedes the log level and generates - /// log messages with the same levels per category as specified by the application configuration. - public LoggingSourceConfiguration(LogLevel level = LogLevel.Debug, bool useAppFilters = false) + public LoggingSourceConfiguration(LogLevel level, LogMessageType messageType, IDictionary filterSpecs, bool useAppFilters) { - _level = level; - _useAppFilters = useAppFilters; + _filterSpecs = ToFilterSpecsString(filterSpecs, useAppFilters); + _keywords = (long)ToKeywords(messageType); + _level = ToEventLevel(level); } public override IList GetProviders() { - string filterSpec = _useAppFilters ? UseAppFilters : FormattableString.Invariant($"*:{_level:G}"); - - var providers = new List() + return new List() { - - // Logging new EventPipeProvider( MicrosoftExtensionsLoggingProviderName, - EventLevel.LogAlways, - (long)(LoggingEventSource.Keywords.JsonMessage | LoggingEventSource.Keywords.FormattedMessage), + _level, + _keywords, arguments: new Dictionary { - - { "FilterSpecs", filterSpec } + { "FilterSpecs", _filterSpecs } } ) }; + } + + private static string ToFilterSpecsString(IDictionary filterSpecs, bool useAppFilters) + { + if (!useAppFilters && (filterSpecs?.Count).GetValueOrDefault(0) == 0) + { + return String.Empty; + } + + StringBuilder filterSpecsBuilder = new StringBuilder(); + + if (useAppFilters) + { + filterSpecsBuilder.Append("UseAppFilters"); + } + + if (null != filterSpecs) + { + foreach (KeyValuePair filterSpec in filterSpecs) + { + if (!string.IsNullOrEmpty(filterSpec.Key)) + { + if (filterSpecsBuilder.Length > 0) + { + filterSpecsBuilder.Append(";"); + } + filterSpecsBuilder.Append(filterSpec.Key); + if (filterSpec.Value.HasValue) + { + filterSpecsBuilder.Append(":"); + filterSpecsBuilder.Append(filterSpec.Value.Value.ToString("G")); + } + } + } + } + + return filterSpecsBuilder.ToString(); + } - return providers; + private static EventLevel ToEventLevel(LogLevel logLevel) + { + switch (logLevel) + { + case LogLevel.None: + throw new NotSupportedException($"{nameof(LogLevel)} {nameof(LogLevel.None)} is not supported as the default log level."); + case LogLevel.Trace: + return EventLevel.LogAlways; + case LogLevel.Debug: + return EventLevel.Verbose; + case LogLevel.Information: + return EventLevel.Informational; + case LogLevel.Warning: + return EventLevel.Warning; + case LogLevel.Error: + return EventLevel.Error; + case LogLevel.Critical: + return EventLevel.Critical; + } + throw new InvalidOperationException($"Unable to convert {logLevel:G} to EventLevel."); + } + + private static EventKeywords ToKeywords(LogMessageType messageType) + { + EventKeywords keywords = 0; + if (messageType.HasFlag(LogMessageType.FormattedMessage)) + { + keywords |= LoggingEventSource.Keywords.FormattedMessage; + } + if (messageType.HasFlag(LogMessageType.JsonMessage)) + { + keywords |= LoggingEventSource.Keywords.JsonMessage; + } + if (messageType.HasFlag(LogMessageType.Message)) + { + keywords |= LoggingEventSource.Keywords.Message; + } + return keywords; } private sealed class LoggingEventSource diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs index 93b49b42a..31db6a531 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipeline.cs @@ -25,7 +25,11 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe protected override MonitoringSourceConfiguration CreateConfiguration() { - return new LoggingSourceConfiguration(Settings.LogLevel, Settings.UseAppFilters); + return new LoggingSourceConfiguration( + Settings.LogLevel, + LogMessageType.FormattedMessage | LogMessageType.JsonMessage, + Settings.FilterSpecs, + Settings.UseAppFilters); } protected override Task OnEventSourceAvailable(EventPipeEventSource eventSource, Func stopSessionAsync, CancellationToken token) diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipelineSettings.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipelineSettings.cs index 4e510038d..cccaefdcf 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipelineSettings.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Logs/EventLogsPipelineSettings.cs @@ -3,17 +3,19 @@ // See the LICENSE file in the project root for more information. using Microsoft.Extensions.Logging; -using System; using System.Collections.Generic; -using System.Text; namespace Microsoft.Diagnostics.Monitoring.EventPipe { internal class EventLogsPipelineSettings : EventSourcePipelineSettings { - public LogLevel LogLevel { get; set; } + // The default log level for all categories + public LogLevel LogLevel { get; set; } = LogLevel.Trace; - //This setting will set the levels to application default. - public bool UseAppFilters { get; set; } + // The logger categories and levels at which log entries are collected. + public IDictionary FilterSpecs { get; set; } + + // This setting will collect logs for the application-defined categories and levels. + public bool UseAppFilters { get; set; } = true; } } diff --git a/src/tests/EventPipeTracee/Program.cs b/src/tests/EventPipeTracee/Program.cs index b85d1379a..ebc86212b 100644 --- a/src/tests/EventPipeTracee/Program.cs +++ b/src/tests/EventPipeTracee/Program.cs @@ -1,4 +1,8 @@ -using Microsoft.Extensions.DependencyInjection; +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using System; using System.Collections.Generic; @@ -8,6 +12,8 @@ namespace EventPipeTracee { class Program { + private const string AppLoggerCategoryName = "AppLoggerCategory"; + static void Main(string[] args) { TestBody(args[0]); @@ -22,10 +28,14 @@ namespace EventPipeTracee serviceCollection.AddLogging(builder => { builder.AddEventSourceLogger(); + // Set application defined levels + builder.AddFilter(null, LogLevel.Error); // Default + builder.AddFilter(AppLoggerCategoryName, LogLevel.Warning); }); using var loggerFactory = serviceCollection.BuildServiceProvider().GetService(); - var logger = loggerFactory.CreateLogger(loggerCategory); + var customCategoryLogger = loggerFactory.CreateLogger(loggerCategory); + var appCategoryLogger = loggerFactory.CreateLogger(AppLoggerCategoryName); Console.Error.WriteLine($"{DateTime.UtcNow} Awaiting start"); Console.Error.Flush(); @@ -36,7 +46,7 @@ namespace EventPipeTracee Console.Error.WriteLine($"{DateTime.UtcNow} Starting test body"); Console.Error.Flush(); - TestBodyCore(logger); + TestBodyCore(customCategoryLogger, appCategoryLogger); //Signal end of test data Console.WriteLine("1"); @@ -52,18 +62,22 @@ namespace EventPipeTracee } //TODO At some point we may want parameters to choose different test bodies. - private static void TestBodyCore(ILogger logger) + private static void TestBodyCore(ILogger customCategoryLogger, ILogger appCategoryLogger) { //Json data is always converted to strings for ActivityStart events. - using (var scope = logger.BeginScope(new Dictionary { + using (var scope = customCategoryLogger.BeginScope(new Dictionary { { "IntValue", "5" }, { "BoolValue", "true" }, { "StringValue", "test" } }.ToList())) { - logger.LogWarning("Some warning message with {arg}", 6); + customCategoryLogger.LogInformation("Some warning message with {arg}", 6); } - logger.LogWarning("Another message"); + customCategoryLogger.LogWarning("Another message"); + + appCategoryLogger.LogInformation("Information message."); + appCategoryLogger.LogWarning("Warning message."); + appCategoryLogger.LogError("Error message."); } } } diff --git a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventLogsPipelineUnitTests.cs b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventLogsPipelineUnitTests.cs index 6bb702810..afe0c304b 100644 --- a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventLogsPipelineUnitTests.cs +++ b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventLogsPipelineUnitTests.cs @@ -2,28 +2,26 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using Microsoft.Diagnostics.NETCore.Client; +using Microsoft.Diagnostics.NETCore.Client.UnitTests; +using Microsoft.Extensions.Logging; using System; -using System.Collections; using System.Collections.Generic; using System.IO; -using System.Runtime.InteropServices; -using System.Text; using System.Text.Json; using System.Threading; using System.Threading.Tasks; -using Microsoft.Diagnostics.Monitoring; -using Microsoft.Diagnostics.Monitoring.EventPipe; -using Microsoft.Diagnostics.NETCore.Client; -using Microsoft.Diagnostics.NETCore.Client.UnitTests; -using Microsoft.Extensions.Logging; using Xunit; using Xunit.Abstractions; -using Xunit.Extensions; namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests { public class EventLogsPipelineUnitTests { + private const string WildcardCagetoryName = "*"; + private const string AppLoggerCategoryName = "AppLoggerCategory"; + private const string LoggerRemoteTestName = "LoggerRemoteTest"; + private readonly ITestOutputHelper _output; public EventLogsPipelineUnitTests(ITestOutputHelper output) @@ -31,19 +29,181 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests _output = output; } + /// + /// Test that all log events are collected if no filters are specified. + /// + [Fact] + public async Task TestLogsAllCategoriesAllLevels() + { + using Stream outputStream = await GetLogsAsync(settings => + { + settings.UseAppFilters = false; + }); + + Assert.True(outputStream.Length > 0, "No data written by logging process."); + + using var reader = new StreamReader(outputStream); + + ValidateLoggerRemoteCategoryInformationMessage(reader); + ValidateLoggerRemoteCategoryWarningMessage(reader); + ValidateAppLoggerCategoryInformationMessage(reader); + ValidateAppLoggerCategoryWarningMessage(reader); + ValidateAppLoggerCategoryErrorMessage(reader); + + Assert.True(reader.EndOfStream, "Expected to have read all entries from stream."); + } + + /// + /// Test that log events at or above the default level are collected. + /// + [Fact] + public async Task TestLogsAllCategoriesDefaultLevel() + { + using Stream outputStream = await GetLogsAsync(settings => + { + settings.UseAppFilters = false; + settings.LogLevel = LogLevel.Warning; + }); + + Assert.True(outputStream.Length > 0, "No data written by logging process."); + + using var reader = new StreamReader(outputStream); + + ValidateLoggerRemoteCategoryWarningMessage(reader); + ValidateAppLoggerCategoryWarningMessage(reader); + ValidateAppLoggerCategoryErrorMessage(reader); + + Assert.True(reader.EndOfStream, "Expected to have read all entries from stream."); + } + + /// + /// Test that log events at the default level are collected for categories without a specified level. + /// + [Fact] + public async Task TestLogsAllCategoriesDefaultLevelFallback() + { + using Stream outputStream = await GetLogsAsync(settings => + { + settings.UseAppFilters = false; + settings.LogLevel = LogLevel.Error; + settings.FilterSpecs = new Dictionary() + { + { AppLoggerCategoryName, null }, + { LoggerRemoteTestName, LogLevel.Trace } + }; + }); + + Assert.True(outputStream.Length > 0, "No data written by logging process."); + + using var reader = new StreamReader(outputStream); + + ValidateLoggerRemoteCategoryInformationMessage(reader); + ValidateLoggerRemoteCategoryWarningMessage(reader); + ValidateAppLoggerCategoryErrorMessage(reader); + + Assert.True(reader.EndOfStream, "Expected to have read all entries from stream."); + } + + /// + /// Test that LogLevel.None is not supported as the default log level. + /// + [Fact] + public Task TestLogsAllCategoriesDefaultLevelNoneNotSupported() + { + return Assert.ThrowsAsync(() => GetLogsAsync(settings => + { + settings.UseAppFilters = false; + settings.LogLevel = LogLevel.None; + })); + } + + /// + /// Test that log events are collected for the categories and levels specified by the application. + /// + [Fact] + public async Task TestLogsUseAppFilters() + { + using Stream outputStream = await GetLogsAsync(); + + Assert.True(outputStream.Length > 0, "No data written by logging process."); + + using var reader = new StreamReader(outputStream); + + ValidateAppLoggerCategoryWarningMessage(reader); + ValidateAppLoggerCategoryErrorMessage(reader); + + Assert.True(reader.EndOfStream, "Expected to have read all entries from stream."); + } + + /// + /// Test that log events are collected for the categories and levels specified by the application + /// and for the categories and levels specified in the filter specs. + /// [Fact] - public async Task TestLogs() + public async Task TestLogsUseAppFiltersAndFilterSpecs() + { + using Stream outputStream = await GetLogsAsync(settings => + { + settings.FilterSpecs = new Dictionary() + { + { LoggerRemoteTestName, LogLevel.Warning } + }; + }); + + Assert.True(outputStream.Length > 0, "No data written by logging process."); + + using var reader = new StreamReader(outputStream); + + ValidateLoggerRemoteCategoryWarningMessage(reader); + ValidateAppLoggerCategoryWarningMessage(reader); + ValidateAppLoggerCategoryErrorMessage(reader); + + Assert.True(reader.EndOfStream, "Expected to have read all entries from stream."); + } + + /// + /// Test that log events are collected for wildcard categories. + /// + [Fact] + public async Task TestLogsWildcardCategory() + { + using Stream outputStream = await GetLogsAsync(settings => + { + settings.UseAppFilters = false; + settings.LogLevel = LogLevel.Critical; + settings.FilterSpecs = new Dictionary() + { + { WildcardCagetoryName, LogLevel.Warning }, + { LoggerRemoteTestName, LogLevel.Error }, + }; + }); + + Assert.True(outputStream.Length > 0, "No data written by logging process."); + + using var reader = new StreamReader(outputStream); + + ValidateAppLoggerCategoryWarningMessage(reader); + ValidateAppLoggerCategoryErrorMessage(reader); + + Assert.True(reader.EndOfStream, "Expected to have read all entries from stream."); + } + + private async Task GetLogsAsync(Action settingsCallback = null) { var outputStream = new MemoryStream(); - await using (var testExecution = StartTraceeProcess("LoggerRemoteTest")) + await using (var testExecution = StartTraceeProcess(LoggerRemoteTestName)) { //TestRunner should account for start delay to make sure that the diagnostic pipe is available. using var loggerFactory = new LoggerFactory(new[] { new TestStreamingLoggerProvider(outputStream) }); var client = new DiagnosticsClient(testExecution.TestRunner.Pid); - var logSettings = new EventLogsPipelineSettings { Duration = Timeout.InfiniteTimeSpan}; + var logSettings = new EventLogsPipelineSettings { Duration = Timeout.InfiniteTimeSpan }; + if (null != settingsCallback) + { + settingsCallback(logSettings); + } await using var pipeline = new EventLogsPipeline(client, logSettings, loggerFactory); await PipelineTestUtilities.ExecutePipelineWithDebugee(pipeline, testExecution); @@ -51,27 +211,31 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests outputStream.Position = 0L; - Assert.True(outputStream.Length > 0, "No data written by logging process."); - - using var reader = new StreamReader(outputStream); + return outputStream; + } - string firstMessage = reader.ReadLine(); - Assert.NotNull(firstMessage); + private static void ValidateLoggerRemoteCategoryInformationMessage(StreamReader reader) + { + string message = reader.ReadLine(); + Assert.NotNull(message); - LoggerTestResult result = JsonSerializer.Deserialize(firstMessage); + LoggerTestResult result = JsonSerializer.Deserialize(message); Assert.Equal("Some warning message with 6", result.Message); - Assert.Equal("LoggerRemoteTest", result.Category); - Assert.Equal("Warning", result.LogLevel); + Assert.Equal(LoggerRemoteTestName, result.Category); + Assert.Equal("Information", result.LogLevel); Assert.Equal("0", result.EventId); Validate(result.Scopes, ("BoolValue", "true"), ("StringValue", "test"), ("IntValue", "5")); Validate(result.Arguments, ("arg", "6")); + } - string secondMessage = reader.ReadLine(); - Assert.NotNull(secondMessage); + private static void ValidateLoggerRemoteCategoryWarningMessage(StreamReader reader) + { + string message = reader.ReadLine(); + Assert.NotNull(message); - result = JsonSerializer.Deserialize(secondMessage); + LoggerTestResult result = JsonSerializer.Deserialize(message); Assert.Equal("Another message", result.Message); - Assert.Equal("LoggerRemoteTest", result.Category); + Assert.Equal(LoggerRemoteTestName, result.Category); Assert.Equal("Warning", result.LogLevel); Assert.Equal("0", result.EventId); Assert.Equal(0, result.Scopes.Count); @@ -79,6 +243,51 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests Assert.Equal(1, result.Arguments.Count); } + private static void ValidateAppLoggerCategoryInformationMessage(StreamReader reader) + { + string message = reader.ReadLine(); + Assert.NotNull(message); + + LoggerTestResult result = JsonSerializer.Deserialize(message); + Assert.Equal("Information message.", result.Message); + Assert.Equal(AppLoggerCategoryName, result.Category); + Assert.Equal("Information", result.LogLevel); + Assert.Equal("0", result.EventId); + Assert.Equal(0, result.Scopes.Count); + //We are expecting only the original format + Assert.Equal(1, result.Arguments.Count); + } + + private static void ValidateAppLoggerCategoryWarningMessage(StreamReader reader) + { + string message = reader.ReadLine(); + Assert.NotNull(message); + + LoggerTestResult result = JsonSerializer.Deserialize(message); + Assert.Equal("Warning message.", result.Message); + Assert.Equal(AppLoggerCategoryName, result.Category); + Assert.Equal("Warning", result.LogLevel); + Assert.Equal("0", result.EventId); + Assert.Equal(0, result.Scopes.Count); + //We are expecting only the original format + Assert.Equal(1, result.Arguments.Count); + } + + private static void ValidateAppLoggerCategoryErrorMessage(StreamReader reader) + { + string message = reader.ReadLine(); + Assert.NotNull(message); + + LoggerTestResult result = JsonSerializer.Deserialize(message); + Assert.Equal("Error message.", result.Message); + Assert.Equal(AppLoggerCategoryName, result.Category); + Assert.Equal("Error", result.LogLevel); + Assert.Equal("0", result.EventId); + Assert.Equal(0, result.Scopes.Count); + //We are expecting only the original format + Assert.Equal(1, result.Arguments.Count); + } + private static void Validate(IDictionary values, params (string key, object value)[] expectedValues) { Assert.NotNull(values); diff --git a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests.csproj b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests.csproj index b2c53b4da..8410ef25c 100644 --- a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests.csproj +++ b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests.csproj @@ -8,7 +8,9 @@ - + + false + diff --git a/src/tests/Microsoft.Diagnostics.Monitoring/Microsoft.Diagnostics.Monitoring.UnitTests.csproj b/src/tests/Microsoft.Diagnostics.Monitoring/Microsoft.Diagnostics.Monitoring.UnitTests.csproj index b6068422e..a7ee91a2f 100644 --- a/src/tests/Microsoft.Diagnostics.Monitoring/Microsoft.Diagnostics.Monitoring.UnitTests.csproj +++ b/src/tests/Microsoft.Diagnostics.Monitoring/Microsoft.Diagnostics.Monitoring.UnitTests.csproj @@ -9,7 +9,9 @@ - + + false +