How Do I Write Stuff?
Logging always becomes a concern sooner or later when one begins work on a new coding project. The ability for our little bundle of software code to communicate with the outside world about what it’s going through is very therapeutic not just for the software, but also for the potentially frustrated user. How one should actually go about implementing this very important infrastructural layer in their creations is a very commonly asked and answered question.
The most common response to those asking for advice on logging is to use one of the established third party logging frameworks. These logging frameworks are some of the most downloaded third party libraries, at least via the standard NuGet repositories — and for good reason, as these logging frameworks can easily provide for all your logging needs, and then some.
What about logging for libraries though?
Ah yes. This is the particular question that is not commonly addressed: how does one go about logging things if they’re making a proper, truly reusable, and general-purposed library? We’re talking about something that isn’t simply a module that is 100% coupled to a particular product’s domain. All recommendations normally given to use one of those third party loggers suddenly evaporate in the light of such questions. Crickets begin chirping.
It’s a bit of a difficult problem. But you probably already know this. The fact you’re even here and reading this article means you’ve sifted through a a mountain of other articles on the topic, probably all saying the same thing.
A lot of people actually seem scared to answer this particular question, I’ve seen many an article writer shy away from it. Well I’m going to come out and just say it: if you’re writing a true library and want to log data or events, using one of the commonly prescribed third party logging frameworks is the wrong thing to do.
What’s the big deal? It’s just a library…
The manifestation of log messages into something tangible is truly an application concern. An application should not have the specific means for satisfying this concern forced upon it by the code libraries it is dependent upon. And that’s essentially what you would be doing by adding a dependency to one of those heavy-duty logging frameworks to your own library.
Often these logging frameworks are configured to do their thing in a program’s App.config
file. You know, that hand editable file only available to the endpoint of a product, not to its parts (outside of code). And, since you can’t provide this configuration, you’re requiring consumers to have to deal with it instead.
More importantly, however, is that because logging is an application matter, you should not go about trying to satisfy it in a reusable library. With libraries, we shouldn’t be concerned at all about logging, but rather messaging. You are responsible for providing the messages regarding the doings of your code; the application is then responsible for logging said messages.
And however you do it, it is best if you can manage to do it using functionality already provided by .NET 5.0’s libraries.
Oooh, Microsoft.Extensions.Logging! Why Not That?
Wait, I just said that we need to be focusing on messaging, not logging…but, oh fine. I’ll bite.
For, I guess decades now, the .NET Framework has always lacked a built-in logging solution. With .NET 5.0, which is basically .NET Core in its “initial” final form, we of course now have Microsoft.Extensions.Logging. I was very excited upon hearing about this library. I figured that I’d now be able to “keep it within the framework” as far as logging was concerned.
Of course, being in the Microsoft.Extensions.*
namespace, it’s not exactly part of the core SDK for .NET 5.0. Being such a common application concern, you’d think that it would be, but I can myself countenance a plethora of reasons as to why it would get stashed in some extensions namespace.
Of course, when I really dug into it, I finally discovered that Microsoft.Extensions.*
is where all the stuff really purposed for ASP.NET development goes. My interest level is already starting to plummet. Anywho, let’s grab it via NuGet and revel in this built-in glory.
Wait…why is a dependency injection framework being installed?!
Immediate alarms start going off in my head. Why does this library have a hard requirement on Microsoft’s DI framework? Seeing this begins to sow seeds of doubt in my mind. Now, dependency injection is a perfectly fine thing to have in your application — assuming its use is merited. Many problems can be solved with it. I’m not making any sort of comment regarding dependency injection at all, I’m just describing my immediate reaction.
Logging is a pretty common and individual software concern; required coupling to a particular dependency injection framework is certainly not something I expect to happen when adding a reference to a logging library.
You may feel that this is an overreaction on my part, but all I’m really doing is viewing this through the lens of designing a general-purposed third party library. We shouldn’t willfully engage in the pollution of our dependency chain.
All of this simply reaffirms my point that logging is not a library concern.
How many classes in the .NET 5.0 SDK use Microsoft.Extensions.Logging
to log their activities? From what I can see (just very quickly searching through the dotnet GitHub source): none. It is an extensions library after all. Surely the .NET SDK is the gold standard for how third party .NET assemblies should behave, so how is the need for diagnostics satisfied by these core libraries?
Why, by satisfying the concern that actually pertains to libraries: messaging! Diagnostic messages are collected and sent into the void for the loggers installed at the very top of the technology stack (i.e. your application) to actually make manifest!
Problem solved! Everything is clear! Erm, except for how to go about doing that whole “messaging” thing properly. How does .NET do that? To answer this, let’s go over some of the mechanisms made available by .NET for this very purpose.
TraceSource: The Old Way. Probably Should Avoid.
Back in the .NET Framework days, the king of the message game was ye olde System.Diagnostics
namespace, and in particular, the Trace
and TraceSource
classes within that namespace. You have probably seen these classes before, and might’ve scratched your head at them a bit, due to the unfortunate reality that a lot of the diagnostical messaging classes have had somewhat limited documentation over the years.
You can find plenty of examples elsewhere on this Internet of ours to see how you can make use of these the Trace
classes. Hopefully you might find something that goes into how to best use them; I could provide that here, or try to, but I write too much already. And, spoiler, I do not recommend making using of TraceSource
anymore, as it is clearly going the way of the dodo. So, there is clearly no need; however, I will explain at least why I feel that way.
For one: I don’t believe it has a single consumer anywhere else in .NET 5.0’s SDK.
A number of classes used to use TraceSource
, perhaps most notably the System.Net
namespace. They no longer do so. It’s not that they don’t exist anymore, but rather they’re using something else. I stumbled upon this realization when looking at one of the most visible parts of the System.Diagnostics
namespace: its configuration.
Back in the .NET Framework days, you used to sometimes run across configuration sections in an App.config
where you could control how messages from various sources were getting routed. Here are some examples.
App.Config for System.Net Traces
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 | < configuration > < system.diagnostics > < sources > < source name = "System.Net" tracemode = "includehex" maxdatasize = "1024" > < listeners > < add name = "System.Net" /> </ listeners > </ source > < source name = "System.Net.Cache" > < listeners > < add name = "System.Net" /> </ listeners > </ source > < source name = "System.Net.Http" > < listeners > < add name = "System.Net" /> </ listeners > </ source > < source name = "System.Net.Sockets" > < listeners > < add name = "System.Net" /> </ listeners > </ source > < source name = "System.Net.WebSockets" > < listeners > < add name = "System.Net" /> </ listeners > </ source > </ sources > < switches > < add name = "System.Net" value = "Verbose" /> < add name = "System.Net.Cache" value = "Verbose" /> < add name = "System.Net.Http" value = "Verbose" /> < add name = "System.Net.Sockets" value = "Verbose" /> < add name = "System.Net.WebSockets" value = "Verbose" /> </ switches > < sharedListeners > < add name = "System.Net" type = "System.Diagnostics.TextWriterTraceListener" initializeData = "network.log" traceOutputOptions = "ProcessId, DateTime" /> </ sharedListeners > </ system.diagnostics > </ configuration > |
I’m showing the above example to you in order to illustrate how one could get at the diagnostic messages being provided by the .NET Framework itself via TraceSource
. Very handy, being able to take a peek at the sacred utterances of the holy Framework itself.
I’m pointing out this use case because if you attempt to use this type of configuration while running on .NET 5.0, nothing will happen. Actually, you’ll most certainly get an exception thrown since .NET no longer has a Machine.config
file anymore. This should not come as a surprise, given how apparently .NET has been moving away from the “old fashioned” System.Configuration
namespace, where XML config files are championed, to the “modern” Microsoft.Extensions.Configuration
approach. Hope you’re a fan of JSON files!
Don’t drink the Kool-Aid. Microsoft.Extensions.* are libraries created with ASP.NET in mind.
Advice peddling their use should not automatically apply to people making non-ASP.NET code. Don’t forget, System.Configuration is actually part of the .NET SDK, and Microsoft.Extensions.* are not.
Even if you overcome the configuration problems (which you won’t, unless you wire up section definitions using .NET Framework, which we’re definitely not interested in), System.Net
no longer uses TraceSource
to do their messaging. Not only is .NET moving on from its old school configuration files, but it appears to be moving away from the TraceSource
API as well.
Let’s look at another problem with the configs which is going to prevent us form using TraceSource
as our solution.
App.Config for Our Library Traces
1 2 3 4 5 6 7 8 9 10 11 12 13 14 | < configuration > < system.diagnostics > < sources > < source name = "MessagesFromOurLibrary" > < listeners > < add name = "OurListener" type = "System.Diagnostics.TextWriterTraceListener" initializeData = "c:\informationOverload.log" /> </ listeners > </ source > </ sources > </ system.diagnostics > </ configuration > |
This is a much simpler configuration. In it we’re playing out a fantasy, where we’re hooking up a listener to a source where messages from our legendary third party library are sent. Indeed, in order for our library’s messaging solution to be viable, the messages being sent must be able to be picked up by all relevant logging frameworks.
From what I’ve seen, most logging frameworks have support for listening to TraceSource
instances, and indeed it was my intention that our message system would be leveraging this configuration system in order to be usable by said logging frameworks, and thus made viable.
Unsurprisingly, in .NET 5.0, the above configuration also does nothing. So our own traces aren’t really useful either.
With the .NET Framework, an application’s configuration would be consulted by TraceSource
upon its initialization, loading all the listeners and the like. This does not occur with .NET 5.0 of course — the old school App.config
is utterly ignored for both the Trace
and TraceSource
classes. They’ve essentially been gutted.
Initialize Routine in TraceSource.cs
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 | private void Initialize() { if (!_initCalled) { lock ( this ) { if (_initCalled) return ; NoConfigInit(); _initCalled = true ; } } } |
This above code gets called sometimes during the initialization of TraceSource
. As you can see, there’s no consideration given at all for loading a configuration file. Clearly, the only reason classes like TraceSource
and Trace
exist is merely for backwards compatibility. We shouldn’t use them for our messaging needs.
Frankly, Microsoft should consider marking the Trace and TraceSource classes as obsolete.
Scanning for usages across the .NET SDK, I can’t find any other classes that are actually making use of them. So, let’s take a look at what Microsoft is using now for sending diagnostic messages from their libraries.
EventSource: The Chosen One. How to Use It.
Say hello to EventSource
, found in the System.Diagnostics.Tracing
namespace. This is the main vehicle for carrying messages now from libraries, in particular the libraries that comprise the new .NET SDK. If it is good enough for them, it will be good enough for us. I’ve always taken a “monkey see, monkey do” approach as far as Microsoft is concerned, and it has served me well over the years.
Unfortunately, the EventSource
class and ETW as a whole is a bit difficult to penetrate. Documentation out there exists, but it still can be a bit of a head scratcher. We’re going to try to take all the available information and see if we can’t devise a reusable messaging system we’ll be able to use within our libraries. Once we do that, we’ll be able to easily capture these messages for logging purposes in our applications, as well as take advantage of the wealth of other ETW-related utilities provided to us already.
The first thing we’ll need is our own concrete derivation of the EventSource
class. It is from here where we will be dumping our diagnostic data into .NET’s event tracing system, so we will be outfitting it with the functionality we’ll need in order to be able to pass the types of payloads that we want. For now, all I can think of that we’ll need to pass is: 1) a message, and 2) an Exception
, if one occurred.
Please note that EventSource
and ETW in general offers a very robust system for logging events, activities, etc. Our goal here is not to implement the most robust EventSource
ever, but rather one we can just pass some messages through. We can do crazier things with it later.
LogSource Class
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 | /// <summary> /// Provides a source for diagnostic messages from Bad Echo technologies to external listeners. /// </summary> [ EventSource (Name = "BadEcho" )] internal sealed class LogSource : EventSource { /// <summary> /// Initializes a new instance of the <see cref="LogSource"/> class. /// </summary> private LogSource () : base ( EventSourceSettings .EtwSelfDescribingEventFormat) { } /// <summary> /// Gets the singular instance of <see cref="LogSource"/>. /// </summary> public static LogSource Instance { get ; } = new (); /// <summary> /// Writes a debug event, its details described by the provided message. /// </summary> /// <param name="message">A debug message describing the details of the event.</param> [ Event (1, Level = EventLevel .Verbose, Keywords = Keywords .MESSAGE_KEYWORD)] public void Debug( string message) { if (!IsEnabled()) return ; WriteEvent(1, message); } /// <summary> /// Writes an informational event, its details described by the provided message. /// </summary> /// <param name="message">An informational message describing the details of the event.</param> [ Event (2, Level = EventLevel .Informational, Keywords = Keywords .MESSAGE_KEYWORD)] public void Info( string message) { if (!IsEnabled()) return ; WriteEvent(2, message); } /// <summary> /// Writes a warning event, its details described by the provided message. /// </summary> /// <param name="message">A warning message describing the details of the event.</param> [ Event (3, Level = EventLevel .Warning, Keywords = Keywords .MESSAGE_KEYWORD)] public void Warning( string message) { if (!IsEnabled()) return ; WriteEvent(3, message); } /// <summary> /// Writes an error event, its details described by the provided message. /// </summary> /// <param name="message">An error message describing the details of the event.</param> [ Event (4, Level = EventLevel .Error, Keywords = Keywords .MESSAGE_KEYWORD)] public void Error( string message) { if (!IsEnabled()) return ; WriteEvent(4, message); } /// <summary> /// Writes a critical error event, its details described by the provided message. /// </summary> /// <param name="message">A critical error message describing the details of the event.</param> [ Event (5, Level = EventLevel .Critical, Keywords = Keywords .MESSAGE_KEYWORD)] public void Critical( string message) { if (!IsEnabled()) return ; WriteEvent(5, message); } /// <summary> /// Writes an error event stemming from an exception, its details described by the provided message and said exception. /// </summary> /// <param name="message">An error message describing the details of the event.</param> /// <param name="exception">The exception that inspired the writing of this event.</param> [ NonEvent ] public void Error( string ? message, Exception exception) { if (!IsEnabled()) return ; ErrorException(message, exception.GetType().FullName ?? string .Empty, exception.Message, exception.HResult, exception.ToString()); } /// <summary> /// Writes a critical error event stemming from an exception, its details described by the provided message and said /// exception. /// </summary> /// <param name="message">A critical error message describing the details of the event.</param> /// <param name="exception">The exception that inspired the writing of this event.</param> [ NonEvent ] public void Critical( string ? message, Exception exception) { if (!IsEnabled()) return ; CriticalException(message, exception.GetType().FullName ?? string .Empty, exception.Message, exception.HResult, exception.ToString()); } [ Event (6, Level = EventLevel .Error, Keywords = Keywords .MESSAGE_KEYWORD | Keywords .EXCEPTION_KEYWORD)] private unsafe void ErrorException( string ? message, string exceptionType, string exceptionMessage, int exceptionHResult, string exceptionVerboseMessage) { fixed ( char * pMessage = message) fixed ( char * pExceptionType = exceptionType) fixed ( char * pExceptionMessage = exceptionMessage) fixed ( char * pExceptionVerboseMessage = exceptionVerboseMessage) { const int eventDataCount = 5; EventData * eventData = stackalloc EventData [eventDataCount]; SetEventData( ref eventData[0], ref message, pMessage); SetEventData( ref eventData[1], ref exceptionType, pExceptionType); SetEventData( ref eventData[2], ref exceptionMessage, pExceptionMessage); SetEventData( ref eventData[3], ref exceptionHResult); SetEventData( ref eventData[4], ref exceptionVerboseMessage, pExceptionVerboseMessage); WriteEventCore(6, eventDataCount, eventData); } } [ Event (7, Level = EventLevel .Critical, Keywords = Keywords .MESSAGE_KEYWORD | Keywords .EXCEPTION_KEYWORD)] private unsafe void CriticalException( string ? message, string exceptionType, string exceptionMessage, int exceptionHResult, string exceptionVerboseMessage) { fixed ( char * pMessage = message) fixed ( char * pExceptionType = exceptionType) fixed ( char * pExceptionMessage = exceptionMessage) fixed ( char * pExceptionVerboseMessage = exceptionVerboseMessage) { const int eventDataCount = 5; EventData * eventData = stackalloc EventData [eventDataCount]; SetEventData( ref eventData[0], ref message, pMessage); SetEventData( ref eventData[1], ref exceptionType, pExceptionType); SetEventData( ref eventData[2], ref exceptionMessage, pExceptionMessage); SetEventData( ref eventData[3], ref exceptionHResult); SetEventData( ref eventData[4], ref exceptionVerboseMessage, pExceptionVerboseMessage); WriteEventCore(7, eventDataCount, eventData); } } [ NonEvent ] [ MethodImpl ( MethodImplOptions .AggressiveInlining)] private static unsafe void SetEventData<T>( ref EventData eventData, ref T value, void * pinnedString = null ) { if ( typeof (T) == typeof ( string ) && Unsafe .SizeOf<T>() == Unsafe .SizeOf< string >()) { var stringValue = Unsafe .As<T, string >( ref value); eventData.DataPointer = ( IntPtr ) pinnedString; eventData.Size = checked ((stringValue.Length + 1) * sizeof ( char )); } else { eventData.DataPointer = ( IntPtr ) Unsafe .AsPointer( ref value); eventData.Size = Unsafe .SizeOf<T>(); } } } |
We can use this EventSource
for pretty much all of our messaging needs in our libraries. A separate Event
has been created for each of the various event levels/severities. A single event that takes an EventLevel
parameter would be nice, however the Event
itself can only ever have one EventLevel
associated with it, at least as far as how the recordkeeping will go.
To aid us in our development efforts, we can make use of a custom EventListener
, which we’ll name DefaultEventListener
in lieu of the old DefaultTraceListener
that would come in to play when using a TraceSource
. It will do much the same thing, namely: output any diagnostic messages sent to it to the debug output window.
DefaultEventListener Class
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 | /// <summary> /// Provides the default logging behavior for Bad Echo's Logging framework, with output limited to an attached debugger. /// </summary> internal sealed class DefaultEventListener : EventListener { /// <inheritdoc/> /// <remarks>Only events from <see cref="LogSource"/> are tracked by this listener.</remarks> protected override void OnEventSourceCreated( EventSource eventSource) { base .OnEventSourceCreated(eventSource); if (eventSource == LogSource .Instance) EnableEvents(eventSource, EventLevel .LogAlways, EventKeywords .All); } /// <inheritdoc/> protected override void OnEventWritten( EventWrittenEventArgs eventData) { var outputMessage = $ @"{eventData.TimeStamp:HH:mm} | {eventData.OSThreadId} | {eventData.Level}" ; outputMessage = $ "{outputMessage} | {(eventData.Payload != null ? eventData.Payload[0] : Strings.LoggingMissingMessage)}" ; if (eventData. Keywords .HasFlag( Keywords .ExceptionKeyword)) { outputMessage = $ @"{outputMessage}{Environment.NewLine} { (eventData.Payload != null ? eventData.Payload[4] : Strings.LoggingMissingException)}" ; } Debugger .Log(0, null , outputMessage); base .OnEventWritten(eventData); } } |
We can then marry the use of these two in a public Logger
class which will ensure that a DefaultEventListener
has been initialized and activated (based on configuration, of course), as well as provide a nice public interface to the rest of the library for sending messages.
Executing the following code:
1 2 3 4 5 | Logger .Critical( "We're doomed." , argumentException); Logger .Critical( "The computer has been unplugged from the wall!" ); Logger .Debug( "The answer to life is 42." ); Logger .Error( "This does not compute. DOES NOT COMPUTE." ); Logger .Info( "Hello there. This is an informational message." ); |
Yields the following output in my Visual Studio’s Output window:
01:29 | 27820 | Critical | We're doomed.
System.ArgumentException: The specified identifier exists, but you were supposed to get it
wrong! IDIOT! (Parameter 'identifierValue')
01:29 | 27820 | Critical | The computer has been unplugged from the wall!
01:29 | 27820 | Verbose | The answer to life is 42.
01:29 | 27820 | Error | This does not compute. DOES NOT COMPUTE.
01:29 | 27820 | Informational | Hello there. This is an informational message.
We now have a functional “logging” framework to use in our libraries to create messages that can be consumed by those complicated, heavy-duty logging frameworks at the application level.
Isn’t Writing Our Own Logging Framework Bad?
By the Gods, of course! To write an actual full featured logging framework, at least one capable of taking diagnostic messages and persisting them in some sort of fashion, all by yourself for a particular project is very foolhardy. Incredible time and care would have to be dedicated towards it in order for it to not cause the rest of your application to be riddled with errors and collapse!
But that’s not what we’ve done here. We’ve merely taken the opportunity to take advantage of the built-in messaging mechanisms provided by .NET for diagnostic purposes. It is expected that an application, if it wishes to record these messages, will make use of a well established and reputable third party framework to consume said messages.
Showing how to wire up an established third party logging framework such as NLog, Serilog, or whatever, to process these kinds of messages is outside the scope of this article. Surely if a logging framework is worth anything at all, it offers the ability to process EventSource
originating messages, the most integral of all the diagnostic mechanisms found in .NET.
We’ll do a follow-up article on this when I get around to publishing some Bad Echo apps.
So, now you know, and hopefully understand, how one goes about logging within the confines of a technologically neutral, “third-party” library. To see this code a bit more fleshed out and in action, consult the Bad Echo code repository.
Thanks for your time, and have a wonderful day/evening/night.