Overexposure to heavy-duty logging frameworks can leave one in a state of derp.

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.

There be some unexpected dependencies here for this logging framework.
Yay for a standard logging framewor…dependency injection? What the hell…!?
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.