|
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.CodeAnalysis;
using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices;
using System.Threading;
using Microsoft.Extensions.Primitives;
namespace Microsoft.Extensions.Logging.EventSource
{
/// <summary>
/// The LoggingEventSource is the bridge from all ILogger based logging to EventSource/EventListener logging.
///
/// You turn this logging on by enabling the EventSource called
///
/// Microsoft-Extensions-Logging
///
/// When you enabled the EventSource, the EventLevel you set is translated in the obvious way to the level
/// associated with the ILogger (thus Debug = verbose, Informational = Informational ... Critical == Critical)
///
/// This allows you to filter by event level in a straightforward way.
///
/// For finer control you can specify a EventSource Argument called
///
/// FilterSpecs
///
/// The FilterSpecs argument is a semicolon separated list of specifications. Where each specification is
///
/// SPEC = // empty spec, same as *
/// | NAME // Just a name the level is the default level
/// | NAME : LEVEL // specifies level for a particular logger (can have a * suffix).
///
/// When "UseAppFilters" is specified in the FilterSpecs, it avoids disabling all categories which happens by default otherwise.
///
/// Where Name is the name of a ILoggger (case matters), Name can have a * which acts as a wildcard
/// AS A SUFFIX. Thus Net* will match any loggers that start with the 'Net'.
///
/// The LEVEL is a number or a LogLevel string. 0=Trace, 1=Debug, 2=Information, 3=Warning, 4=Error, Critical=5
/// This specifies the level for the associated pattern. If the number is not specified, (first form
/// of the specification) it is the default level for the EventSource.
///
/// First match is used if a particular name matches more than one pattern.
///
/// In addition the level and FilterSpec argument, you can also set EventSource Keywords. See the Keywords
/// definition below, but basically you get to decide if you wish to have
///
/// * Keywords.Message - You get the event with the data in parsed form.
/// * Keywords.JsonMessage - you get an event with the data in parse form but as a JSON blob (not broken up by argument ...)
/// * Keywords.FormattedMessage - you get an event with the data formatted as a string
///
/// It is expected that you will turn only one of these keywords on at a time, but you can turn them all on (and get
/// the same data logged three different ways.
///
/// Example Usage
///
/// This example shows how to use an EventListener to get ILogging information
///
/// class MyEventListener : EventListener {
/// protected override void OnEventSourceCreated(EventSource eventSource) {
/// if (eventSource.Name == "Microsoft-Extensions-Logging") {
/// // initialize a string, string dictionary of arguments to pass to the EventSource.
/// // Turn on loggers matching App* to Information, everything else (*) is the default level (which is EventLevel.Error)
/// var args = new Dictionary<string, string>() { { "FilterSpecs", "App*:Information;*" } };
/// // Set the default level (verbosity) to Error, and only ask for the formatted messages in this case.
/// EnableEvents(eventSource, EventLevel.Error, LoggingEventSource.Keywords.FormattedMessage, args);
/// }
/// }
/// protected override void OnEventWritten(EventWrittenEventArgs eventData) {
/// // Look for the formatted message event, which has the following argument layout (as defined in the LoggingEventSource.
/// // FormattedMessage(LogLevel Level, int FactoryID, string LoggerName, string EventId, string FormattedMessage);
/// if (eventData.EventName == "FormattedMessage")
/// Console.WriteLine("Logger {0}: {1}", eventData.Payload[2], eventData.Payload[4]);
/// }
/// }
/// </summary>
[EventSource(Name = "Microsoft-Extensions-Logging")]
public sealed class LoggingEventSource : System.Diagnostics.Tracing.EventSource
{
/// <summary>
/// This is public from an EventSource consumer point of view, but since these definitions
/// are not needed outside this class
/// </summary>
public static class Keywords
{
/// <summary>
/// Meta events are events about the LoggingEventSource itself (that is they did not come from ILogger
/// </summary>
public const EventKeywords Meta = (EventKeywords)1;
/// <summary>
/// Turns on the 'Message' event when ILogger.Log() is called. It gives the information in a programmatic (not formatted) way
/// </summary>
public const EventKeywords Message = (EventKeywords)2;
/// <summary>
/// Turns on the 'FormatMessage' event when ILogger.Log() is called. It gives the formatted string version of the information.
/// </summary>
public const EventKeywords FormattedMessage = (EventKeywords)4;
/// <summary>
/// Turns on the 'MessageJson' event when ILogger.Log() is called. It gives JSON representation of the Arguments.
/// </summary>
public const EventKeywords JsonMessage = (EventKeywords)8;
}
/// <summary>
/// The one and only instance of the LoggingEventSource.
/// </summary>
internal static readonly LoggingEventSource Instance = new LoggingEventSource();
// It's important to have _filterSpec initialization here rather than in ctor
// base ctor might call OnEventCommand and set filter spec
// having assignment in ctor would overwrite the value
private LoggerFilterRule[] _filterSpec = Array.Empty<LoggerFilterRule>();
private CancellationTokenSource? _cancellationTokenSource;
private const string UseAppFilters = "UseAppFilters";
private const string WriteEventCoreSuppressionJustification = "WriteEventCore is safe when eventData object is a primitive type which is in this case.";
private const string WriteEventDynamicDependencySuppressionJustification = "DynamicDependency attribute will ensure that the required properties are not trimmed.";
private static readonly char[] s_semicolon = new[] { ';' };
private static readonly char[] s_colon = new[] { ':' };
private LoggingEventSource() : base(EventSourceSettings.EtwSelfDescribingEventFormat)
{
}
/// <summary>
/// FormattedMessage() is called when ILogger.Log() is called. and the FormattedMessage keyword is active
/// This only gives you the human readable formatted message.
/// </summary>
[Event(1, Keywords = Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventCoreSuppressionJustification)]
internal unsafe void FormattedMessage(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, string FormattedMessage)
{
if (IsEnabled())
{
LoggerName ??= "";
EventName ??= "";
FormattedMessage ??= "";
fixed (char* loggerName = LoggerName)
fixed (char* eventName = EventName)
fixed (char* formattedMessage = FormattedMessage)
{
const int eventDataCount = 6;
EventData* eventData = stackalloc EventData[eventDataCount];
SetEventData(ref eventData[0], ref Level);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);
SetEventData(ref eventData[3], ref EventId);
SetEventData(ref eventData[4], ref EventName, eventName);
SetEventData(ref eventData[5], ref FormattedMessage, formattedMessage);
WriteEventCore(1, eventDataCount, eventData);
}
}
}
/// <summary>
/// Message() is called when ILogger.Log() is called. and the Message keyword is active
/// This gives you the logged information in a programmatic format (arguments are key-value pairs)
/// </summary>
[Event(2, Keywords = Keywords.Message, Level = EventLevel.LogAlways)]
[DynamicDependency(DynamicallyAccessedMemberTypes.PublicProperties, typeof(KeyValuePair<string, string>))]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventDynamicDependencySuppressionJustification)]
internal void Message(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, ExceptionInfo Exception, IEnumerable<KeyValuePair<string, string?>> Arguments)
{
if (IsEnabled())
{
WriteEvent(2, Level, FactoryID, LoggerName, EventId, EventName, Exception, Arguments);
}
}
/// <summary>
/// ActivityStart is called when ILogger.BeginScope() is called
/// </summary>
[Event(3, Keywords = Keywords.Message | Keywords.FormattedMessage, Level = EventLevel.LogAlways, ActivityOptions = EventActivityOptions.Recursive)]
[DynamicDependency(DynamicallyAccessedMemberTypes.PublicProperties, typeof(KeyValuePair<string, string>))]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventDynamicDependencySuppressionJustification)]
internal void ActivityStart(int ID, int FactoryID, string LoggerName, IEnumerable<KeyValuePair<string, string?>> Arguments)
{
if (IsEnabled())
{
WriteEvent(3, ID, FactoryID, LoggerName, Arguments);
}
}
[Event(4, Keywords = Keywords.Message | Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventCoreSuppressionJustification)]
internal unsafe void ActivityStop(int ID, int FactoryID, string LoggerName)
{
if (IsEnabled())
{
LoggerName ??= "";
fixed (char* loggerName = LoggerName)
{
const int eventDataCount = 3;
EventData* eventData = stackalloc EventData[eventDataCount];
SetEventData(ref eventData[0], ref ID);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);
WriteEventCore(4, eventDataCount, eventData);
}
}
}
[Event(5, Keywords = Keywords.JsonMessage, Level = EventLevel.LogAlways)]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventCoreSuppressionJustification)]
internal unsafe void MessageJson(LogLevel Level, int FactoryID, string LoggerName, int EventId, string? EventName, string ExceptionJson, string ArgumentsJson, string FormattedMessage)
{
if (IsEnabled())
{
LoggerName ??= "";
EventName ??= "";
ExceptionJson ??= "";
ArgumentsJson ??= "";
FormattedMessage ??= "";
fixed (char* loggerName = LoggerName)
fixed (char* eventName = EventName)
fixed (char* exceptionJson = ExceptionJson)
fixed (char* argumentsJson = ArgumentsJson)
fixed (char* formattedMessage = FormattedMessage)
{
const int eventDataCount = 8;
EventData* eventData = stackalloc EventData[eventDataCount];
SetEventData(ref eventData[0], ref Level);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);
SetEventData(ref eventData[3], ref EventId);
SetEventData(ref eventData[4], ref EventName, eventName);
SetEventData(ref eventData[5], ref ExceptionJson, exceptionJson);
SetEventData(ref eventData[6], ref ArgumentsJson, argumentsJson);
SetEventData(ref eventData[7], ref FormattedMessage, formattedMessage);
WriteEventCore(5, eventDataCount, eventData);
}
}
}
[Event(6, Keywords = Keywords.JsonMessage | Keywords.FormattedMessage, Level = EventLevel.LogAlways, ActivityOptions = EventActivityOptions.Recursive)]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventCoreSuppressionJustification)]
internal unsafe void ActivityJsonStart(int ID, int FactoryID, string LoggerName, string ArgumentsJson)
{
if (IsEnabled())
{
LoggerName ??= "";
ArgumentsJson ??= "";
fixed (char* loggerName = LoggerName)
fixed (char* argumentsJson = ArgumentsJson)
{
const int eventDataCount = 4;
EventData* eventData = stackalloc EventData[eventDataCount];
SetEventData(ref eventData[0], ref ID);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);
SetEventData(ref eventData[3], ref ArgumentsJson, argumentsJson);
WriteEventCore(6, eventDataCount, eventData);
}
}
}
[Event(7, Keywords = Keywords.JsonMessage | Keywords.FormattedMessage, Level = EventLevel.LogAlways)]
[UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:RequiresUnreferencedCode",
Justification = WriteEventCoreSuppressionJustification)]
internal unsafe void ActivityJsonStop(int ID, int FactoryID, string LoggerName)
{
if (IsEnabled())
{
LoggerName ??= "";
fixed (char* loggerName = LoggerName)
{
const int eventDataCount = 3;
EventData* eventData = stackalloc EventData[eventDataCount];
SetEventData(ref eventData[0], ref ID);
SetEventData(ref eventData[1], ref FactoryID);
SetEventData(ref eventData[2], ref LoggerName, loggerName);
WriteEventCore(7, eventDataCount, eventData);
}
}
}
/// <inheritdoc />
protected override void OnEventCommand(EventCommandEventArgs command)
{
if (command.Command is EventCommand.Update or EventCommand.Enable)
{
if (!command.Arguments!.TryGetValue("FilterSpecs", out string? filterSpec))
{
filterSpec = string.Empty; // This means turn on everything.
}
SetFilterSpec(filterSpec);
}
else if (command.Command == EventCommand.Disable)
{
SetFilterSpec(null); // This means disable everything.
}
}
/// <summary>
/// Set the filtering specification. null means turn off all loggers. Empty string is turn on all providers.
/// </summary>
/// <param name="filterSpec">The filter specification to set.</param>
[NonEvent]
private void SetFilterSpec(string? filterSpec)
{
_filterSpec = ParseFilterSpec(filterSpec, GetDefaultLevel());
FireChangeToken();
}
[NonEvent]
internal IChangeToken GetFilterChangeToken()
{
CancellationTokenSource cts = LazyInitializer.EnsureInitialized(ref _cancellationTokenSource, () => new CancellationTokenSource());
return new CancellationChangeToken(cts.Token);
}
[NonEvent]
private void FireChangeToken()
{
CancellationTokenSource? tcs = Interlocked.Exchange(ref _cancellationTokenSource, null);
tcs?.Cancel();
}
/// <summary>
/// Given a set of specifications Pat1:Level1;Pat1;Level2 ... Where
/// Pat is a string pattern (a logger Name with a optional trailing wildcard * char)
/// and Level is a number 0 (Trace) through 5 (Critical).
///
/// The :Level can be omitted (thus Pat1;Pat2 ...) in which case the level is 1 (Debug).
///
/// A completely empty string act like * (all loggers set to Debug level).
///
/// The first specification that 'loggers' Name matches is used.
/// </summary>
[NonEvent]
private static LoggerFilterRule[] ParseFilterSpec(string? filterSpec, LogLevel defaultLevel)
{
if (filterSpec == string.Empty)
{
return new[] { new LoggerFilterRule(typeof(EventSourceLoggerProvider).FullName, null, defaultLevel, null) };
}
if (filterSpec == null)
{
// All event source loggers are disabled by default
return new[] { new LoggerFilterRule(typeof(EventSourceLoggerProvider).FullName, null, LogLevel.None, null) };
}
var rules = new List<LoggerFilterRule>();
int ruleStringsStartIndex = 0;
string[] ruleStrings = filterSpec.Split(s_semicolon, StringSplitOptions.RemoveEmptyEntries);
if (ruleStrings.Length > 0 && ruleStrings[0].Equals(UseAppFilters, StringComparison.OrdinalIgnoreCase))
{
// Avoid adding default rule to disable event source loggers
ruleStringsStartIndex = 1;
}
else
{
rules.Add(new LoggerFilterRule(typeof(EventSourceLoggerProvider).FullName, null, LogLevel.None, null));
}
for (int i = ruleStringsStartIndex; i < ruleStrings.Length; i++)
{
string rule = ruleStrings[i];
LogLevel level = defaultLevel;
string[] parts = rule.Split(s_colon, 2);
string loggerName = parts[0];
if (loggerName.Length == 0)
{
continue;
}
if (loggerName[loggerName.Length - 1] == '*')
{
loggerName = loggerName.Substring(0, loggerName.Length - 1);
}
if (parts.Length == 2)
{
if (!TryParseLevel(defaultLevel, parts[1], out level))
{
continue;
}
}
rules.Add(new LoggerFilterRule(typeof(EventSourceLoggerProvider).FullName, loggerName, level, null));
}
return rules.ToArray();
}
/// <summary>
/// Parses the level specification (which should look like :N where n is a number 0 (Trace)
/// through 5 (Critical). It can also be an empty string (which means 1 (Debug) and ';' marks
/// the end of the specification. This specification should start at spec[curPos]
/// It returns the value in 'ret' and returns true if successful. If false is returned ret is left unchanged.
/// </summary>
[NonEvent]
private static bool TryParseLevel(LogLevel defaultLevel, string levelString, out LogLevel ret)
{
ret = defaultLevel;
if (levelString.Length == 0)
{
// No :Num spec means Debug
ret = defaultLevel;
return true;
}
int level;
switch (levelString)
{
case "Trace":
ret = LogLevel.Trace;
break;
case "Debug":
ret = LogLevel.Debug;
break;
case "Information":
ret = LogLevel.Information;
break;
case "Warning":
ret = LogLevel.Warning;
break;
case "Error":
ret = LogLevel.Error;
break;
case "Critical":
ret = LogLevel.Critical;
break;
default:
if (!int.TryParse(levelString, out level))
{
return false;
}
if (!(LogLevel.Trace <= (LogLevel)level && (LogLevel)level <= LogLevel.None))
{
return false;
}
ret = (LogLevel)level;
break;
}
return true;
}
[NonEvent]
private LogLevel GetDefaultLevel()
{
EventKeywords allMessageKeywords = Keywords.Message | Keywords.FormattedMessage | Keywords.JsonMessage;
if (IsEnabled(EventLevel.Verbose, allMessageKeywords))
{
return LogLevel.Debug;
}
if (IsEnabled(EventLevel.Informational, allMessageKeywords))
{
return LogLevel.Information;
}
if (IsEnabled(EventLevel.Warning, allMessageKeywords))
{
return LogLevel.Warning;
}
if (IsEnabled(EventLevel.Error, allMessageKeywords))
{
return LogLevel.Error;
}
return LogLevel.Critical;
}
[NonEvent]
internal LoggerFilterRule[] GetFilterRules()
{
return _filterSpec;
}
[NonEvent]
[MethodImpl(MethodImplOptions.AggressiveInlining)]
private static unsafe void SetEventData<T>(ref EventData eventData, ref T value, void* pinnedString = null)
{
if (typeof(T) == typeof(string))
{
string str = (value as string)!;
#if DEBUG
fixed (char* rePinnedString = str)
{
Debug.Assert(pinnedString == rePinnedString);
}
#endif
eventData.DataPointer = (IntPtr)pinnedString;
eventData.Size = checked((str.Length + 1) * sizeof(char)); // size is specified in bytes, including null wide char
}
else
{
eventData.DataPointer = (IntPtr)Unsafe.AsPointer(ref value);
#pragma warning disable 8500 // sizeof of managed types
eventData.Size = sizeof(T);
#pragma warning restore 8500
}
}
}
}
|