jimbrownaptoware-blog

[jimbrownaptoware-blog]

.NET Core Platform Agnostic Tracing

While working on a project recently I recommended implementing tracing in some components using .NET Event Sources and ETW. The company were using .NET Core and mix of Windows and Linux operating systems. The architecture team were looking for a platform agnsotic solution. ETW can't work on Linux because it's built into the Windows Kernal and also the clue's in the name Event Tracing for Windows.

Setup

I investigated and immediately found out about LTTng which could do everything needed:

tracing event sources

real time tracing

filtering

I bashed together a .NET Core console application that would trace a message using an Event Source and quickly tested it on Windows using an ETW trace viewer tool.

Event Source

using System.Diagnostics.Tracing; namespace ConsoleApp1 { [EventSource(Name = "TestEventSource")] public class TestEventSource : EventSource { public static readonly TestEventSource Current = new TestEventSource(); private TestEventSource() : base() { } public static class Keywords { public const EventKeywords Messages = (EventKeywords)0x1L; } private const int MessageEventId = 1; [Event(MessageEventId, Level = EventLevel.Informational, Message = "{0}", Keywords = Keywords.Messages)] public void Message(string message) { if (this.IsEnabled()) { WriteEvent(MessageEventId, message); } } } }

Main Program

using System; namespace ConsoleApp1 { class Program { static void Main(string[] args) { Console.WriteLine("Running trace event source test app..."); TestEventSource.Current.Message("Hello World!"); TestEventSource2.Current.Message("World Hello!"); } } }

Then I created a Ubuntu.18.04-x64 server in Azure and transferred the application. To build the .NET Core application for Ubuntu I used this command:

dotnet publish -c release -r ubuntu.18.04-x64

To install LTTng I used the following terminal commands:

apt-get install lttng-tools

apt-get install lttng-modules-dkms

apt-get install liblttng-ust-dev

LTTng has great docs here.

Then I installed the .NET Core SDK following these instructions.

Tracing to file storage

Run the following terminal commands:

lttng create jimssession lttng enable-event --userspace --tracepoint DotNETRuntime:EventSource lttng start

In order for this to work I had to enable the DotNETRuntime environment variable COMPlus_EnableEventLog. There are two ways to do this:

1. With the command to run the .NET Core App

COMPlus_EnableEventLog=1 dotnet ./publish/ConsoleApp1.dll

2. Seperately in the terminal and then it stays set

export COMPlus_EnableEventLog=1

Then you can just run your .NET Core app without using the 'dotnet' command:

./publish/ConsoleApp1

To view your trace output I used a tool called Babeltrace. I think this was with the LTTng install so should already be available.

Run these commands in the terminal to view your trace output:

lttng stop Babeltrace lttng-traces/jimssession-20181124-183519

When you initialised the session you will have been notified of this trace output folder path. Your traces should be shown below after executing the Babeltrace command above.

Real-Time Tracing (live-tracing)

For real time tracing I had to use two terminal sessions seeing as I was using one to execute my console application but if you have an application already running on a Linux machine then you wouldn't need to do that.

Here's what I did:

In terminal 1:

lttng create jimssession --live

lttng enable-event --userspace --tracepoint DotNETRuntime:EventSource

In terminal 2:

babeltrace --input-format=lttng-live net://localhost/host/machineName/jimssession

In terminal 1:

lttng start

and execute the app:

./publish/ConsoleApp1

Here's the output:

There are great instructions for this by Pavel Makhov here and you can easily do remote tracing using the --set-url parmater.

Filtering

With ETW you can filter by event source and that's very useful for reducing noise when you're debugging. I was expecting that the enable-event command parameter --tracepoint would be the event source name and to be honest spent a lot of time scratching my head and wondering why nothing was being traced until I figured out the parameter value must be DotNETRuntime:EventSource. Obviously if it were the event source name then filtering would be easy because you would just enable-event for each source you wished to trace. Well it is easy anyway because there is another parameter on the enable-event command --filter. So to filter by event source I was able to do this:

lttng enable-event --userspace --tracepoint DotNETRuntime:EventSource --filter '(EventSourceName == "TestEventSource")'

The filter syntax is well document here.

Using NET Core ILogger

As ILogger is the preferred method for Logging in NET Core I had to investigate the possibility of using this for tracing also. Event Source tracing is supported in NET Core using ILogger through the EventSource provider but there are some pretty extreme limitations. The docs also say "The provider is cross-platform, but there are no event collection and display tools yet for Linux or macOS" - Not true in a way as I was at least able to collect some traces on Linux using LTTng.

For the default setup you can just use logging.AddEventSourceLogger() as documented here or in my case because I was using a console app I had to do this:

using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; namespace ILoggerEventSourceLogging { class ILoggerTestEventSource { private readonly ILogger _logger; public ILoggerTestEventSource(ILogger logger) { _logger = logger; } static void Main(string[] args) { var serviceCollection = new ServiceCollection(); ConfigureServices(serviceCollection); var serviceProvider = serviceCollection.BuildServiceProvider(); var program = serviceProvider.GetService(); program._logger.LogInformation("Hello World"); } private static void ConfigureServices(IServiceCollection services) { services.AddLogging(configure => configure.AddEventSourceLogger()) .Configure(options => options.MinLevel = LogLevel.Information) .AddTransient(); } } }

So I tested this first with my goto ETW trace viewer and I didn't see any output? So I decided seeing as the docs here suggest using the Microsoft PerfView utility (download the exe for here) then I would try that.

I did manage to view my trace output as promised however I wasn't overly satisfied because I'm not a big fan of the PerfView interface:

You can see above that ILogger outputs four traces for each single log statement in your code:

EventSourceMessage

FormattedMessage

Message

MessageJson

Not having any success with my goto ETW trace viewer tool I decided to see if LTTng would capture the events on Linux. It did and here's the output:

First, you can see the four ILogger traces, second there is an error on the 'EventSourceMessage' Exception in Command Processing for EventSource Microsoft-Extensions-Logging: Object reference not set to an instance of an object.

So this suggests to me that the NET Core default EventSource provider does not conform properly to the EventSource format rules.

So to make this work with my goto ETW trace viewer tool and error free with LTTng I had to use a custom provider with ILogger.

Here's what you need:

The logging provider classes I used can be found here:

https://github.com/aspnet/Extensions/tree/master/src/Logging/Logging.EventSource/src

Event Source Logger

using System; using System.Collections.Generic; using System.Diagnostics.Tracing; using System.IO; using System.Linq; using System.Threading; using Microsoft.Extensions.Logging; using Newtonsoft.Json; namespace ILoggerEventSourceLogging { internal class EventSourceLogger : ILogger { private static int _activityIds; private readonly ILoggerEventSource _eventSource; private readonly int _factoryId; internal static readonly LogLevel LoggingDisabled = LogLevel.None + 1; public EventSourceLogger(string categoryName, int factoryId, ILoggerEventSource eventSource, EventSourceLogger next) { CategoryName = categoryName; // Default is to turn off logging Level = LoggingDisabled; _factoryId = factoryId; _eventSource = eventSource; Next = next; } public string CategoryName { get; } private LogLevel _level; public LogLevel Level { get { // need to check if the filter spec and internal event source level has changed and update the loggers level if it has _eventSource.ApplyFilterSpec(); return _level; } set { _level = value; } } // Loggers created by a single provider form a linked list public EventSourceLogger Next { get; } public bool IsEnabled(LogLevel logLevel) { return logLevel >= Level; } public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { if (!IsEnabled(logLevel)) { return; } // See if they want the formatted message if (_eventSource.IsEnabled(EventLevel.Critical, _eventSource.FormattedMessageKeyword)) { var message = formatter(state, exception); _eventSource.FormattedMessage(logLevel, _factoryId, CategoryName, eventId.ToString(), message); } #if !NO_EVENTSOURCE_COMPLEX_TYPE_SUPPORT // See if they want the message as its component parts. if (_eventSource.IsEnabled(EventLevel.Critical, _eventSource.MessageKeyword)) { var exceptionInfo = GetExceptionInfo(exception); var arguments = GetProperties(state); _eventSource.ExceptionMessage(logLevel, _factoryId, CategoryName, eventId.ToString(), exceptionInfo, arguments); } #endif // See if they want the json message if (_eventSource.IsEnabled(EventLevel.Critical, _eventSource.JsonMessageKeyword)) { var exceptionJson = "{}"; if (exception != null) { var exceptionInfo = GetExceptionInfo(exception); var exceptionInfoData = new[] { new KeyValuePair("TypeName", exceptionInfo.TypeName), new KeyValuePair("Message", exceptionInfo.Message), new KeyValuePair("HResult", exceptionInfo.HResult.ToString()), new KeyValuePair("VerboseMessage", exceptionInfo.VerboseMessage), }; exceptionJson = ToJson(exceptionInfoData); } var arguments = GetProperties(state); _eventSource.MessageJson(logLevel, _factoryId, CategoryName, eventId.ToString(), exceptionJson, ToJson(arguments)); } } public IDisposable BeginScope(TState state) { if (!IsEnabled(LogLevel.Critical)) { return NoopDisposable.Instance; } var id = Interlocked.Increment(ref _activityIds); // If JsonMessage is on, use JSON format if (_eventSource.IsEnabled(EventLevel.Critical, _eventSource.JsonMessageKeyword)) { var arguments = GetProperties(state); _eventSource.ActivityJsonStart(id, _factoryId, CategoryName, ToJson(arguments)); return new ActivityScope(_eventSource, CategoryName, id, _factoryId, true); } else { #if !NO_EVENTSOURCE_COMPLEX_TYPE_SUPPORT var arguments = GetProperties(state); _eventSource.ActivityStart(id, _factoryId, CategoryName, arguments); #else _eventSource.ActivityStart(id, _factoryID, CategoryName); #endif return new ActivityScope(_eventSource, CategoryName, id, _factoryId, false); } } private class ActivityScope : IDisposable { private readonly string _categoryName; private readonly int _activityId; private readonly int _factoryId; private readonly bool _isJsonStop; private readonly ILoggerEventSource _eventSource; public ActivityScope(ILoggerEventSource eventSource, string categoryName, int activityId, int factoryId, bool isJsonStop) { _categoryName = categoryName; _activityId = activityId; _factoryId = factoryId; _isJsonStop = isJsonStop; _eventSource = eventSource; } public void Dispose() { if (_isJsonStop) { _eventSource.ActivityJsonStop(_activityId, _factoryId, _categoryName); } else { _eventSource.ActivityStop(_activityId, _factoryId, _categoryName); } } } private class NoopDisposable : IDisposable { public static readonly NoopDisposable Instance = new NoopDisposable(); public void Dispose() { } } private ExceptionInfo GetExceptionInfo(Exception exception) { var exceptionInfo = new ExceptionInfo(); if (exception != null) { exceptionInfo.TypeName = exception.GetType().FullName; exceptionInfo.Message = exception.Message; exceptionInfo.HResult = exception.HResult; exceptionInfo.VerboseMessage = exception.ToString(); } return exceptionInfo; } private IEnumerable> GetProperties(object state) { var arguments = new List>(); var asKeyValues = state as IEnumerable>; if (asKeyValues != null) { arguments.AddRange(from keyValue in asKeyValues where keyValue.Key != null select new KeyValuePair(keyValue.Key, keyValue.Value?.ToString())); } return arguments; } private string ToJson(IEnumerable> keyValues) { var sw = new StringWriter(); var writer = new JsonTextWriter(sw) { DateFormatString = "O" }; writer.WriteStartObject(); foreach (var keyValue in keyValues) { writer.WritePropertyName(keyValue.Key, true); writer.WriteValue(keyValue.Value); } writer.WriteEndObject(); return sw.ToString(); } } }

Event Source Logger Provider

using System.Diagnostics.Tracing; using Microsoft.Extensions.Logging; namespace ILoggerEventSourceLogging { public class EventSourceLoggerProvider : ILoggerProvider { // A small integer that uniquely identifies the LoggerFactory assoicated with this LoggingProvider. // Zero is illegal (it means we are uninitialized), and have to be added to the factory. private int _factoryId; private LogLevel _defaultLevel; private string _filterSpec; private EventSourceLogger _loggers; private readonly ILoggerEventSource _eventSource; public EventSourceLoggerProvider(ILoggerEventSource eventSource, EventSourceLoggerProvider next = null) { _eventSource = eventSource; Next = next; } public EventSourceLoggerProvider Next { get; } public Microsoft.Extensions.Logging.ILogger CreateLogger(string categoryName) { // need to check if the filter spec and internal event source level has changed and update the _defaultLevel if it has _eventSource.ApplyFilterSpec(); var newLogger = _loggers = new EventSourceLogger(categoryName, _factoryId, _eventSource, _loggers); newLogger.Level = ParseLevelSpecs(_filterSpec, _defaultLevel, newLogger.CategoryName); return newLogger; } public void Dispose() { // Turn off any logging SetFilterSpec(null); } // Sets the filtering for a particular logger provider public void SetFilterSpec(string filterSpec) { _filterSpec = filterSpec; _defaultLevel = GetDefaultLevel(); // Update the levels of all the loggers to match what the filter specification asks for. for (var logger = _loggers; logger != null; logger = logger.Next) { logger.Level = ParseLevelSpecs(filterSpec, _defaultLevel, logger.CategoryName); } if (_factoryId == 0) { // Compute an ID for the Factory. It is its position in the list (starting at 1, we reserve 0 to mean unstarted). _factoryId = 1; for (var cur = Next; cur != null; cur = cur.Next) { _factoryId++; } } } private LogLevel GetDefaultLevel() { var allMessageKeywords = _eventSource.MessageKeyword | _eventSource.FormattedMessageKeyword | _eventSource.JsonMessageKeyword; if (_eventSource.IsEnabled(EventLevel.Informational, allMessageKeywords)) { return _eventSource.IsEnabled(EventLevel.Verbose, allMessageKeywords) ? LogLevel.Debug : LogLevel.Information; } if (_eventSource.IsEnabled(EventLevel.Warning, allMessageKeywords)) { return LogLevel.Warning; } return _eventSource.IsEnabled(EventLevel.Error, allMessageKeywords) ? LogLevel.Error : LogLevel.Critical; } private LogLevel ParseLevelSpecs(string filterSpec, LogLevel defaultLevel, string loggerName) { if (filterSpec == null) { return EventSourceLogger.LoggingDisabled; // Null means disable. } if (filterSpec == string.Empty) { return defaultLevel; } var level = EventSourceLogger.LoggingDisabled; // If the logger does not match something, it is off. // See if logger.Name matches a _filterSpec pattern. var namePos = 0; var specPos = 0; for (; ; ) { if (namePos < loggerName.Length) { if (filterSpec.Length <= specPos) { break; } var specChar = filterSpec[specPos++]; var nameChar = loggerName[namePos++]; if (specChar == nameChar) { continue; } // We allow wildcards at the end. if (specChar == '*' && ParseLevel(defaultLevel, filterSpec, specPos, ref level)) { return level; } } else if (ParseLevel(defaultLevel, filterSpec, specPos, ref level)) { return level; } // Skip to the next spec in the ; separated list. specPos = filterSpec.IndexOf(';', specPos) + 1; if (specPos <= 0) // No ; done. { break; } namePos = 0; // Reset where we are searching in the name. } return level; } private bool ParseLevel(LogLevel defaultLevel, string spec, int specPos, ref LogLevel ret) { var endPos = spec.IndexOf(';', specPos); if (endPos < 0) { endPos = spec.Length; } if (specPos == endPos) { // No :Num spec means Debug ret = defaultLevel; return true; } if (spec[specPos++] != ':') { return false; } var levelStr = spec.Substring(specPos, endPos - specPos); switch (levelStr) { 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: int level; if (!int.TryParse(levelStr, out level)) { return false; } if (!(LogLevel.Trace <= (LogLevel)level && (LogLevel)level <= LogLevel.None)) { return false; } ret = (LogLevel)level; break; } return true; } } }

Exception Info

namespace ILoggerEventSourceLogging { #if !NO_EVENTSOURCE_COMPLEX_TYPE_SUPPORT [System.Diagnostics.Tracing.EventData(Name = "ExceptionInfo")] #endif public class ExceptionInfo { public string TypeName { get; set; } public string Message { get; set; } public int HResult { get; set; } public string VerboseMessage { get; set; } // This is the ToString() of the Exception } }

Logger Event Source Interface

using System.Collections.Generic; using System.Diagnostics.Tracing; using Microsoft.Extensions.Logging; namespace ILoggerEventSourceLogging { public interface ILoggerEventSource { ILoggerProvider CreateLoggerProvider(); void FormattedMessage(LogLevel level, int factoryId, string loggerName, string eventId, string formattedMessage); void ExceptionMessage(LogLevel level, int factoryId, string loggerName, string eventId, ExceptionInfo exception, IEnumerable<KeyValuePair<string, string>> arguments); void ActivityStart(int id, int factoryId, string loggerName, IEnumerable> arguments); void ActivityStop(int id, int factoryId, string loggerName); void MessageJson(LogLevel level, int factoryId, string loggerName, string eventId, string exceptionJson, string argumentsJson); void ActivityJsonStart(int id, int factoryId, string loggerName, string argumentsJson); void ActivityJsonStop(int id, int factoryId, string loggerName); bool IsEnabled(EventLevel level, EventKeywords keywords); void ApplyFilterSpec(); EventKeywords MetaKeyword { get; } EventKeywords MessageKeyword { get; } EventKeywords FormattedMessageKeyword { get; } EventKeywords JsonMessageKeyword { get; } } }

Event Source

using System.Collections.Generic; using System.Diagnostics.Tracing; using System.Text; using Microsoft.Extensions.Logging; namespace ILoggerEventSourceLogging { [EventSource(Name = "NetCoreLoggerEventSource")] public class NetCoreLoggerEventSource : EventSource, ILoggerEventSource { public static readonly NetCoreLoggerEventSource Current = new NetCoreLoggerEventSource(); #region Keywords public static class Keywords { // The four keywords below are part of the ASPNetCore logging implementation public const EventKeywords Meta = (EventKeywords)8; /// <summary> /// Turns on the 'Message' event when ILogger.Log() is called. It gives the information in a programatic (not formatted) way /// </summary> public const EventKeywords Message = (EventKeywords)16; /// <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)32; /// <summary> /// Turns on the 'MessageJson' event when ILogger.Log() is called. It gives JSON representation of the Arguments. /// </summary> public const EventKeywords JsonMessage = (EventKeywords)64; } #endregion #region Code for implementing the ASPNet core logging ILoggerEventSource interface internal static readonly LogLevel LoggingDisabled = LogLevel.None + 1; private readonly object _providerLock = new object(); private string _filterSpec; private EventSourceLoggerProvider _loggingProviders; private bool _checkLevel; public ILoggerProvider CreateLoggerProvider() { lock (_providerLock) { var newLoggerProvider = new EventSourceLoggerProvider(this, _loggingProviders); _loggingProviders = newLoggerProvider; // If the EventSource has already been turned on. set the filters. if (_filterSpec != null) { newLoggerProvider.SetFilterSpec(_filterSpec); } return newLoggerProvider; } } public EventKeywords MetaKeyword => Keywords.Meta; public EventKeywords MessageKeyword => Keywords.Message; public EventKeywords FormattedMessageKeyword => Keywords.FormattedMessage; public EventKeywords JsonMessageKeyword => Keywords.JsonMessage; /// <summary> /// FormattedMessage() is called when ILogger.Log() is called. and the FormattedMessage keyword is active /// This only gives you the human reasable formatted message. /// </summary> #region FormattedMessage events public void FormattedMessage(LogLevel level, int factoryId, string loggerName, string eventId, string formattedMessage) { formattedMessage = formattedMessage ?? ""; switch (level) { case LogLevel.Critical: FormattedMessageCritical(factoryId, loggerName, eventId, formattedMessage); break; case LogLevel.Error: FormattedMessageError(factoryId, loggerName, eventId, formattedMessage); break; case LogLevel.Warning: FormattedMessageWarning(factoryId, loggerName, eventId, formattedMessage); break; case LogLevel.Information: FormattedMessageInformational(factoryId, loggerName, eventId, formattedMessage); break; case LogLevel.Debug: case LogLevel.Trace: FormattedMessageVerbose(factoryId, loggerName, eventId, formattedMessage); break; } } private const int FormattedMessageIdCritical = 111; private const int FormattedMessageIdError = 112; private const int FormattedMessageIdWarning = 113; private const int FormattedMessageIdInformational = 114; private const int FormattedMessageIdVerbose = 115; [Event(FormattedMessageIdCritical, Keywords = Keywords.FormattedMessage, Level = EventLevel.Critical, Message = "{3}")] private void FormattedMessageCritical(int factoryId, string loggerName, string eventId, string formattedMessage) { WriteEvent(FormattedMessageIdCritical, factoryId, loggerName, eventId, formattedMessage); } [Event(FormattedMessageIdError, Keywords = Keywords.FormattedMessage, Level = EventLevel.Error, Message = "{3}")] private void FormattedMessageError(int factoryId, string loggerName, string eventId, string formattedMessage) { WriteEvent(FormattedMessageIdError, factoryId, loggerName, eventId, formattedMessage); } [Event(FormattedMessageIdWarning, Keywords = Keywords.FormattedMessage, Level = EventLevel.Warning, Message = "{3}")] private void FormattedMessageWarning(int factoryId, string loggerName, string eventId, string formattedMessage) { WriteEvent(FormattedMessageIdWarning, factoryId, loggerName, eventId, formattedMessage); } [Event(FormattedMessageIdInformational, Keywords = Keywords.FormattedMessage, Level = EventLevel.Informational, Message = "{3}")] private void FormattedMessageInformational(int factoryId, string loggerName, string eventId, string formattedMessage) { WriteEvent(FormattedMessageIdInformational, factoryId, loggerName, eventId, formattedMessage); } [Event(FormattedMessageIdVerbose, Keywords = Keywords.FormattedMessage, Level = EventLevel.Verbose, Message = "{3}")] private void FormattedMessageVerbose(int factoryId, string loggerName, string eventId, string formattedMessage) { WriteEvent(FormattedMessageIdVerbose, factoryId, loggerName, eventId, formattedMessage); } #endregion FormattedMessage events #region ExceptionMessage events [NonEvent] public void ExceptionMessage(LogLevel level, int factoryId, string loggerName, string eventId, ExceptionInfo exception, IEnumerable> arguments) { var message = new StringBuilder(); foreach (var arg in arguments) message.Append($"{arg.Key} - {arg.Value}"); ExceptionMessage(level, factoryId, loggerName, eventId, exception.Message, message.ToString()); } public void ExceptionMessage(LogLevel level, int factoryId, string loggerName, string eventId, string exception, string message) { exception = exception ?? ""; message = message ?? ""; switch (level) { case LogLevel.Critical: ExceptionMessageCritical(factoryId, loggerName, eventId, exception, message); break; case LogLevel.Error: ExceptionMessageError(factoryId, loggerName, eventId, exception, message); break; case LogLevel.Warning: ExceptionMessageWarning(factoryId, loggerName, eventId, exception, message); break; case LogLevel.Information: ExceptionMessageInformational(factoryId, loggerName, eventId, exception, message); break; case LogLevel.Debug: case LogLevel.Trace: ExceptionMessageVerbose(factoryId, loggerName, eventId, exception, message); break; } } private const int ExceptionMessageIdCritical = 121; private const int ExceptionMessageIdError = 122; private const int ExceptionMessageIdWarning = 123; private const int ExceptionMessageIdInformational = 124; private const int ExceptionMessageIdVerbose = 125; [Event(ExceptionMessageIdCritical, Keywords = Keywords.Message, Level = EventLevel.Critical, Message = "{4}")] public void ExceptionMessageCritical(int factoryId, string loggerName, string eventId, string exception, string message) { WriteEvent(ExceptionMessageIdCritical, factoryId, loggerName, eventId, exception, message); } [Event(ExceptionMessageIdError, Keywords = Keywords.Message, Level = EventLevel.Error, Message = "{4}")] public void ExceptionMessageError(int factoryId, string loggerName, string eventId, string exception, string message) { WriteEvent(ExceptionMessageIdError, factoryId, loggerName, eventId, exception, message); } [Event(ExceptionMessageIdWarning, Keywords = Keywords.Message, Level = EventLevel.Warning, Message = "{4}")] public void ExceptionMessageWarning(int factoryId, string loggerName, string eventId, string exception, string message) { WriteEvent(ExceptionMessageIdWarning, factoryId, loggerName, eventId, exception, message); } [Event(ExceptionMessageIdInformational, Keywords = Keywords.Message, Level = EventLevel.Informational, Message = "{4}")] public void ExceptionMessageInformational(int factoryId, string loggerName, string eventId, string exception, string message) { WriteEvent(ExceptionMessageIdInformational, factoryId, loggerName, eventId, exception, message); } [Event(ExceptionMessageIdVerbose, Keywords = Keywords.Message, Level = EventLevel.Verbose, Message = "{4}")] public void ExceptionMessageVerbose(int factoryId, string loggerName, string eventId, string exception, string message) { WriteEvent(ExceptionMessageIdVerbose, factoryId, loggerName, eventId, exception, message); } #endregion ExceptionMessage events #region MessageJson events public void MessageJson(LogLevel level, int factoryId, string loggerName, string eventId, string exceptionJson, string argumentsJson) { exceptionJson = exceptionJson ?? ""; argumentsJson = argumentsJson ?? ""; switch (level) { case LogLevel.Critical: MessageJsonCritical(factoryId, loggerName, eventId, exceptionJson, argumentsJson); break; case LogLevel.Error: MessageJsonError(factoryId, loggerName, eventId, exceptionJson, argumentsJson); break; case LogLevel.Warning: MessageJsonWarning(factoryId, loggerName, eventId, exceptionJson, argumentsJson); break; case LogLevel.Information: MessageJsonInformational(factoryId, loggerName, eventId, exceptionJson, argumentsJson); break; case LogLevel.Debug: case LogLevel.Trace: MessageJsonVerbose(factoryId, loggerName, eventId, exceptionJson, argumentsJson); break; } } private const int MessageJsonIdCritical = 131; private const int MessageJsonIdError = 132; private const int MessageJsonIdWarning = 133; private const int MessageJsonIdInformational = 134; private const int MessageJsonIdVerbose = 135; [Event(MessageJsonIdCritical, Keywords = Keywords.JsonMessage, Level = EventLevel.Critical, Message = "{4}")] private void MessageJsonCritical(int factoryId, string loggerName, string eventId, string exceptionJson, string argumentsJson) { WriteEvent(MessageJsonIdCritical, factoryId, loggerName, eventId, exceptionJson, argumentsJson); } [Event(MessageJsonIdError, Keywords = Keywords.JsonMessage, Level = EventLevel.Error, Message = "{4}")] private void MessageJsonError(int factoryId, string loggerName, string eventId, string exceptionJson, string argumentsJson) { WriteEvent(MessageJsonIdError, factoryId, loggerName, eventId, exceptionJson, argumentsJson); } [Event(MessageJsonIdWarning, Keywords = Keywords.JsonMessage, Level = EventLevel.Warning, Message = "{4}")] private void MessageJsonWarning(int factoryId, string loggerName, string eventId, string exceptionJson, string argumentsJson) { WriteEvent(MessageJsonIdWarning, factoryId, loggerName, eventId, exceptionJson, argumentsJson); } [Event(MessageJsonIdInformational, Keywords = Keywords.JsonMessage, Level = EventLevel.Informational, Message = "{4}")] private void MessageJsonInformational(int factoryId, string loggerName, string eventId, string exceptionJson, string argumentsJson) { WriteEvent(MessageJsonIdInformational, factoryId, loggerName, eventId, exceptionJson, argumentsJson); } [Event(MessageJsonIdVerbose, Keywords = Keywords.JsonMessage, Level = EventLevel.Verbose, Message = "{4}")] private void MessageJsonVerbose(int factoryId, string loggerName, string eventId, string exceptionJson, string argumentsJson) { WriteEvent(MessageJsonIdVerbose, factoryId, loggerName, eventId, exceptionJson, argumentsJson); } #endregion MessageJson events [NonEvent] public void ActivityStart(int id, int factoryId, string loggerName, IEnumerable> arguments) { var message = new StringBuilder(); foreach (var arg in arguments) message.Append($"{arg.Key} - {arg.Value}"); ActivityStart(id, factoryId, loggerName, message.ToString()); } /// <summary> /// ActivityStart is called when ILogger.BeginScope() is called /// </summary> private const int ActivityStartId = 141; [Event(ActivityStartId, Keywords = Keywords.Message | Keywords.FormattedMessage, Level = EventLevel.Informational, ActivityOptions = EventActivityOptions.Recursive, Message = "{3}")] public void ActivityStart(int id, int factoryId, string loggerName, string message) { WriteEvent(ActivityStartId, id, factoryId, loggerName, message); } private const int ActivityStopId = 142; [Event(ActivityStopId, Keywords = Keywords.Message | Keywords.FormattedMessage, Level = EventLevel.Informational, Message = "")] public void ActivityStop(int id, int factoryId, string loggerName) { WriteEvent(ActivityStopId, id, factoryId, loggerName); } private const int ActivityJsonStartId = 143; [Event(ActivityJsonStartId, Keywords = Keywords.JsonMessage | Keywords.FormattedMessage, Level = EventLevel.Informational, ActivityOptions = EventActivityOptions.Recursive, Message = "{3}")] public void ActivityJsonStart(int id, int factoryId, string loggerName, string argumentsJson) { WriteEvent(ActivityJsonStartId, id, factoryId, loggerName, argumentsJson); } private const int ActivityJsonStopId = 144; [Event(ActivityJsonStopId, Keywords = Keywords.JsonMessage | Keywords.FormattedMessage, Level = EventLevel.Informational, Message = "")] public void ActivityJsonStop(int id, int factoryId, string loggerName) { WriteEvent(ActivityJsonStopId, id, factoryId, loggerName); } protected override void OnEventCommand(EventCommandEventArgs command) { lock (_providerLock) { if (command.Command == EventCommand.Update || command.Command == EventCommand.Enable) { string filterSpec; if (!command.Arguments.TryGetValue("FilterSpecs", out filterSpec)) { filterSpec = string.Empty; // This means turn on everything. } SetFilterSpec(filterSpec); } else if (command.Command == EventCommand.Update || command.Command == EventCommand.Disable) { SetFilterSpec(null); // This means disable everything. } } } /// <summary> /// Set the filtering specifcation. null means turn off all loggers. Empty string is turn on all providers. /// </summary> /// [NonEvent] private void SetFilterSpec(string filterSpec) { _filterSpec = filterSpec; // In .NET 4.5.2 the internal EventSource level hasn't been correctly set // when this callback is invoked. To still have the logger behave correctly // in .NET 4.5.2 we delay checking the level until the logger is used the first // time after this callback. _checkLevel = true; } [NonEvent] public void ApplyFilterSpec() { lock (_providerLock) { if (_checkLevel) { for (var cur = _loggingProviders; cur != null; cur = cur.Next) { cur.SetFilterSpec(_filterSpec); } _checkLevel = false; } } } #endregion } }

Main Program

using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; namespace ILoggerEventSourceLogging { class Program { private readonly ILogger _logger; public Program(ILogger logger) { _logger = logger; } static void Main(string[] args) { var serviceCollection = new ServiceCollection(); ConfigureServices(serviceCollection); var serviceProvider = serviceCollection.BuildServiceProvider(); var program = serviceProvider.GetService(); program._logger.LogInformation("Hello World from Jim"); } private static void ConfigureServices(IServiceCollection services) { services.AddLogging(configure => configure.ClearProviders().AddProvider(NetCoreLoggerEventSource.Current.CreateLoggerProvider())) .Configure(options => options.MinLevel = LogLevel.Information) .AddTransient(); } } }

So using this custom log provider I had success and was able to view the traces in my usual ETW trace viewer tool and also on Linux there were now no errors in the output:

and no more errors on Linux with LTTng:

References

http://blogs.microsoft.co.il/sasha/2017/03/30/tracing-runtime-events-in-net-core-on-linux/

https://lttng.org/blog/2018/08/28/bringing-dotnet-perf-analysis-to-linux/

https://lttng.org/

https://lttng.org/docs/v2.10/#doc-lttng-live

https://lttng.org/docs/v2.10/#doc-ubuntu

https://lttng.org/man/1/lttng-enable-event/v2.10/

https://lttng.org/blog/2017/11/22/lttng-ust-blocking-mode/

https://pavelmakhov.com/2017/01/lttng-streaming

https://www.microsoft.com/net/download/linux-package-manager/ubuntu18-04/sdk-current

https://lttng.org/man/1/lttng-enable-event/v2.10/#doc-filter-syntax

http://ctpd.dorsal.polymtl.ca/system/files/TracingSummit2015-LTTngFilteringeBPF.pdf

https://blogs.msdn.microsoft.com/luisdem/2017/03/19/net-core-1-1-how-to-publish-a-self-contained-application

https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-2.1#eventsource-provider

https://www.blinkingcaret.com/2018/02/14/net-core-console-logging/

https://codeblog.dotsandbrackets.com/profiling-net-core-app-linux/