The Art of Logging
- The Art of Logging
What is Logging
At its simplest logging could be described as being a form of running commentary on an application and that commentary can be directed to the console or some external place such as a file on the local hard drive.
Consider for a moment the following method.
public decimal Divide (int a, int b)
{
return a / b;
}
It’s clearly somewhat contrived but it’s a good example to describe what we might need to do in order to obtain that ‘running commentary’ that we want. Let’s start with knowing that we have entered and exited the method. Incidentally I used Linqpad for this example as it makes a great scratch pad for testing little bits of code like this.
I’ll add a couple of lines of code to the method to tell me when it’s entered and exited.
public decimal Divide (int a, int b)
{
Console.WriteLine("Entering the Divide Method.");
return a / b ;
Console.WriteLine("Leaving the Divide Method.");
}
That probably took me about a minute to do, although a competent touch typist could well be quicker, however remember that minute. If the code is run the following is output to the console.
Entering the Divide Method.
We now know when we have entered the method but once the method returns the result anything else is out of scope and won’t get called so we don’t actually know that it has finished. I could get around that by introducing a try / finally block.
public decimal Divide (int a, int b)
{
Console.WriteLine("Entering the Divide Method.");
try
{
return a / b;
}
finally
{
Console.WriteLine("Leaving the Divide Method.");
}
}
This produces the following result.
Entering the Divide Method.
Leaving the Divide Method.
That’s probably added another minute of additional work to my method. Now it would probably be useful to know what parameters are actually being passed to this method and also what result is being returned. Time to adjust our method once again.
public decimal Divide (int a, int b)
{
Console.WriteLine($"Entering the Divide Method, with the following parameters; a = {a} and b = {b}.");
decimal result = 0;
try
{
result = a / b;
return result;
}
finally
{
Console.WriteLine($"Leaving the Divide Method, with the following result: {result}.");
}
}
This produces the following;
Entering the Divide Method, with the following parameters; a = 2 and b = 1. Leaving the Divide Method, with the following result 2.
Now that’s much more informative but we’ve had to add a variable to contain the result so that we could report it and rejig out two WriteLine statements. Probably another couple of minutes used up. There’s still and obvious flaw though that we haven’t covered, suppose the method throws an error. We will need to know about that. Time for some more alterations.
public decimal Divide (int a, int b)
{
Console.WriteLine($"Entering the Divide Method, with the following parameters; a = {a} and b = {b}.");
decimal result = 0;
try
{
result = a / b;
return result;
}
catch (Exception e)
{
Console.WriteLine($"The Divide method encountered an error. The error message was {e.Message}.");
return result;
}
finally
{
Console.WriteLine($"Leaving the Divide Method. with the following result: {result}.");
}
}
Now id we contrive a divide by zero exception by passing in 2 and 0 as parameters we get the following;
Entering the Divide Method, with the following parameters; a = 2 and b = 0.
The Divide method encountered an error. The error message was Attempted to divide by zero.
Leaving the Divide Method. with the following result: 0.
That is much more informative but we’ve had to add an awful lot of additional code to the method to get some meaningful commentary out. If we want a meaningful running commentary on our application we’re going to have to do that to every method that we want to keep track of. If we say that all of the changes would probably have added an extra two or so minutes work for a proficient touch typist, once multiplied over several methods in each project of a solution that time soon mounts up and in reality this is really pretty straightforward boiler plate code.
You can start to see why so many developers, despite appreciating what logging can do for them, don’t actually go to the trouble of fully logging their work. Surely there must be an easier way to do this. Fortunately there is.
Simple Logging with Metalama
Without going into too much detail here as to how Metalama does what it does we will say that essentially Metalama is able to add code to your code at compile time. By decorating your code with an attribute, or attributes, you effectively instruct Metalama to execute a pre-defined template over the code that you’ve just decorated with said attribute(s). As has already been mentioned in the introduction there will be a freely available solution that implements Metalama logging. With that in mind the steps that we take now may seem a little over the top but they are what you would want to be doing if you decide to create your own custom logging solution with Metalama.
To begin with we’ll create a simple logging solution that provides exactly the same amount of information as we have previously hand coded into our method. To remind ourselves we want to know which method we’re in, what parameters, if any, were passed to it and when the method was exited and what, if any, result was passed onwards. As with our previous handwritten example we will for the moment confine our output to the terminal console window. We will do this with the aid of what in Metalama is referred to as an aspect. When we have finisher writing it we will be able to decorate any block of code that we want logging applied to with a simple [Log] attribute and at compile time Metalama will, as if by magic, insert all the necessary code that needs to be added to provide us with the logging that we want. For the sake of clarification I’ll be working in the latest version of Visual Studio (Visual Studio 2022 v17.5 at the time of writing) with the .Net 6 SDK installed and the Metalama Visual Studio Extension.
Getting Started
We’ll start off by creating a new Solution / Project. It will be a class library based on .Net Standard 2.0 and it will be named ‘
Once created add the Metalama.Framework Nuget package to the project (selecting the latest stable version). Now delete the default Class1 and add a new class called LogAttribute.
namespace VtlSoftware.Metalama.Logging
{
public class LogAttribute
{
}
}
We want to log methods so we’ll have this class inherit from Metalama’s OverrideMethodAspect, which in turn will require that we actively implement the OverrideMethod() method.
public class LogAttribute : OverrideMethodAspect
{
public override dynamic? OverrideMethod()
{
throw new NotImplementedException();
}
}
Note that dynamic is nullable
At this point well take a slight diversion and create a helper method that will construct our log strings.
An Interpolated String Builder
Create a new static method BuildInterpolatedString that returns a Metalama InterpolatedStringBuilder. In its most basic form it will look like this;
private static InterpolatedStringBuilder BuildInterpolatedString(bool includeOutParameters)
{
var stringBuilder = new InterpolatedStringBuilder();
// Include the type and method name.
stringBuilder.AddText(meta.Target.Type.ToDisplayString(CodeDisplayFormat.MinimallyQualified));
stringBuilder.AddText(".");
stringBuilder.AddText(meta.Target.Method.Name);
stringBuilder.AddText("(");
return stringBuilder;
}
The most important thing to understand from what has just been added is the Metalama class meta and its member Target. In the Metalama documentation it is defined as ‘the entry point for the meta model which can be used in templates to inspect the target code or access other features of the template language’.
In this case meta.Target will refer to the code that has the [Log] attribute added to it. The meta.Target.Type will refer to the class in which the method being logged resides and the meta.Target.Method.Name should, one hopes, be self- explanatory. Just a quick note about the CodeDisplayFormat. In it’s MinimallyQualified form we’ll get just the <type name>.<method name> back. If we were to opt for FullyQualified we’d get <namespace or alias name>.<type name>.<method name>.
private static InterpolatedStringBuilder BuildInterpolatedString(bool includeOutParameters)
{
var stringBuilder = new InterpolatedStringBuilder();
// Include the type and method name.
stringBuilder.AddText(meta.Target.Type.ToDisplayString(CodeDisplayFormat.MinimallyQualified));
stringBuilder.AddText(".");
stringBuilder.AddText(meta.Target.Method.Name);
stringBuilder.AddText("(");
// Include a placeholder for each parameter.
var i = meta.CompileTime(0);
foreach (var p in meta.Target.Parameters)
{
var comma = i > 0 ? ", " : "";
if (p.RefKind == RefKind.Out && !includeOutParameters)
{
// When the parameter is 'out', we cannot read the value.
stringBuilder.AddText($"{comma}{p.Name} = <out> ");
}
else
{
// Otherwise, add the parameter value.
stringBuilder.AddText($"{comma}{p.Name} = /\{\{/");
stringBuilder.AddExpression(p.Value);
stringBuilder.AddText("}");
}
i++;
}
stringBuilder.AddText(")");
return stringBuilder;
}
Now that you have a basic understanding of the meta class you can probably work out for yourself exactly what is being done here. Essentially if the method has parameters we are reading through them one by one, obtaining both their name and value, and adding them to our stringBuilder. Because we can’t read the value of ‘out’ parameters those, if there are any, are being specifically excluded.
Getting Started (reprieved)
Having created a helper method to construct an informative string message containing the basic name information of our method and its parameters we can return to our LogAttribute and start to flesh that out. We’ll start by creating the message that provides that information, and we’ll be doing that in the overridden OverrideMethod().
public override dynamic OverrideMethod()
{
// Write entry message.
var entryMessage = BuildInterpolatedString(false);
entryMessage.AddText(" started.");
Console.WriteLine(entryMessage.ToValue());
}
Next we’ll want to run the actual method code. If the method is void (it won’t return anything) then we’re just interested in knowing if it succeeded or failed. If it actually returns something we need to know what it returned in addition to whether or not it failed. A try catch block will allow us to determine failure and report back on it. Our overridden method should now look this.
public override dynamic OverrideMethod()
{
// Write entry message.
var entryMessage = BuildInterpolatedString(false);
entryMessage.AddText(" started.");
Console.WriteLine(entryMessage.ToValue());
try
{
// Invoke the method and store the result in a variable.
var result = meta.Proceed();
// Display the success message. The message is different when the method is void.
var successMessage = BuildInterpolatedString(true);
if (meta.Target.Method.ReturnType.Is(typeof(void)))
{
// When the method is void, display a constant text.
successMessage.AddText(" succeeded.");
}
else
{
// When the method has a return value, add it to the message.
successMessage.AddText(" returned ");
successMessage.AddExpression(result);
successMessage.AddText(".");
}
Console.WriteLine(successMessage.ToValue());
return result;
}
catch (Exception e)
{
// Display the failure message.
var failureMessage = BuildInterpolatedString(false);
failureMessage.AddText(" failed: ");
failureMessage.AddExpression(e.Message);
Console.WriteLine(failureMessage.ToValue());
throw;
}
}
In the try part of the block we have just added we are using meta.Proceed to actually run our method, and depending upon whether or not it is a void we go on to report success as either a plain “succeeded” where there is no return value to log or “returned” where there is.
Potential failure is catered for in the catch block and here we log a “failed” message along with the actual failure message to give us some idea as to why it actually failed.
That’s pretty much it. We’ll build our project and if successful build a release version.
A Console for Testing
With that done let’s create a new Visual studio solution. This time were going to create a .Net 6 console application and we’ll add as a reference our VtlSoftware.MetaLama.Logging.dll from the release bin of our Metalama.Logging solution. You will also need to add a direct reference to the Metalama.Framework Nuget Package.
Now in the new console app add a new class called Calculator and within that four simple methods.
internal static class Calculator
{
public static double Add(double x, double y) => x + y;
public static double Subtract(double x, double y) => x - y;
public static double Divide(double x, double y) => x / y;
public static int DivideInt(int x, int y) => x / y;
}
As we have a reference to out Metalama.Logging project we can add logging to these methods really easily by the simple process of adding a [Log] attribute.
internal static class Calculator
{
[Log]
public static double Add(double x, double y) => x + y;
[Log]
public static double Subtract(double x, double y) => x - y;
[Log]
public static double Divide(double x, double y) => x / y;
[Log]
public static int DivideInt(int x, int y) => x / y;
}
In Visual Studio (but only visual studio as it alone can utilise the Metalama extension for Visual Studio) place the current on the name of one of your methods and invoke the right click context menu. Once it opens select ‘Show Metalama diff’.
If we look at the Add method in the new code window that has opened we can see the code that Metalama has added to our method to enable logging. Moreover if we scroll through all of the methods we can see consistent boilerplate logging code has been added to each method to which we added the [Log] attribute.
[Log]
public static double Add(double x, double y)
{
Console.WriteLine($"Calculator.Add(x = }, y = }) started.");
try
{
double result;
result = x + y;
Console.WriteLine($"Calculator.Add(x = }, y = }) returned {result}.");
return (double)result;
}
catch (Exception e)
{
Console.WriteLine($"Calculator.Add(x = }, y = }) failed: {e.Message}");
throw;
}
}
I’m sure you’ll agree that that is impressive. More to the point that’s a lot of code that you haven’t actually had to write yourself.
Let’s quickly put this to the test. In the program file in the main method add the following code.
static void Main(string[] args)
{
try
{
Calculator.Add(1, 1);
Calculator.Subtract(2, 1);
// the following will report infinity as the result as we are dealing with doubles
Calculator.Divide(2, 0);
//the following will report a Divide by zero exception as we're dealing with integers
Calculator.DivideInt(2, 0);
}
catch
{
}
}
Run the program and observe the logging sent to the console.
Calculator.Add(x = {1}, y = {1}) started.
Calculator.Add(x = {1}, y = {1}) returned 2.
Calculator.Subtract(x = {2}, y = {1}) started.
Calculator.Subtract(x = {2}, y = {1}) returned 1.
Calculator.Divide(x = {2}, y = {0}) started.
Calculator.Divide(x = {2}, y = {0}) returned 8.
Calculator.DivideInt(x = {2}, y = {0}) started.
Calculator.DivideInt(x = {2}, y = {0}) failed: Attempted to divide by zero.
By all accounts that’s pretty impressive and all you had to do was add a log attribute to each method you wanted to see a log entry for. It should be apparent that you can save a lot of time by using Metalama to provide logging for your application(s).
Refining our log entries
We’ve seen how efficiently our method parameters have been returned but that might not always be such a good idea. What about methods that handle things like passwords? Do we really want to pass our passwords as unredacted plain strings into logs that in theory, at least, anyone could read? There could be serious, possibly even legal implications if we do that, so let’s look at ways to avoid that sort of thing happening.
We’ll start by adding a new static class to our solution called Strings, to which we’ll add a contrived Login method and add our log attribute to it, finally calling it from our main method.
internal static class Strings
{
[Log]
public static void Login(string username, string password)
{
Console.WriteLine("This is the Login Method");
}
}
static void Main(string[] args)
{
try
{
//Calculator.Add(1, 1);
//Calculator.Subtract(2, 1);
//// the following will report infinity as the result as we are dealing with doubles
//Calculator.Divide(2, 0);
////the following will report a Divide by zero exception as we're dealing with integers
//Calculator.DivideInt(2, 0);
Strings.Login("dom", "mySuperSecretPassword");
} catch
{
}
}
When we run this we get;
Strings.Login(username = {dom}, password = {mySuperSecretPassword}) started.
This is the Login Method
Strings.Login(username = {dom}, password = {mySuperSecretPassword}) succeeded.
Oops!
To correct this we’ll return to our Metalama.Logging project and add a new static class SensitiveParameterFilter, which we’ll decorate with the Metalama [CompileTime] attribute to ensure that this class is available to Metalama at compile time only (where it will be of the most use to us).
Within that we’ll add the following;
[CompileTime]
internal static class SensitiveParameterFilter
{
private static readonly string[] _sensitiveNames = new[] { "password", "credential", "pwd" };
public static bool IsSensitive(IParameter parameter)
{
if(parameter.Attributes.OfAttributeType(typeof(NotLoggedAttribute)).Any())
{
return true;
}
if(_sensitiveNames.Any(n => parameter.Name.ToLowerInvariant().Contains(n)))
{
return true;
}
return false;
}
}
Let’s look at what is going on here. To begin with we creating a static read only string array of what we will consider to be potential parameter names for parameters that we might wish to either avoid logging altogether or if we do log them do so in a way in which their actual value is redacted. NB As is, this array is fixed. To be really useful it ought to be dynamic and possibly read from an external source. Next up we have a Boolean method IsSensitive that returns true if either a parameter is marked with the [NotLogged] attribute (see below) or the parameter name is in our list of names declared earlier.
[AttributeUsage(AttributeTargets.Parameter | AttributeTargets.ReturnValue ]
public sealed class NotLoggedAttribute : Attribute
{
}
Next we want to make an adjustment to our LogAttribute OverirideMethod() method
public override dynamic? OverrideMethod()
{
// Write entry message.
var entryMessage = BuildInterpolatedString(false);
entryMessage.AddText(" started.");
Console.WriteLine(entryMessage.ToValue());
try
{
// Invoke the method and store the result in a variable.
var result = meta.Proceed();
// Display the success message. The message is different when the method is void.
var successMessage = BuildInterpolatedString(true);
if(meta.Target.Method.ReturnType.Is(typeof(void)))
{
// When the method is void, display a constant text.
successMessage.AddText(" succeeded.");
}
else
{
// When the method has a return value, add it to the message.
successMessage.AddText(" returned ");
//check to see if we are dealing with sensitive data
if (SensitiveParameterFilter.IsSensitive(meta.Target.Method.ReturnParameter))
{
successMessage.AddText("<redacted>");
}
else
{
successMessage.AddExpression(result);
}
successMessage.AddText(".");
}
Console.WriteLine(successMessage.ToValue());
return result;
} catch(Exception e)
{
// Display the failure message.
var failureMessage = BuildInterpolatedString(false);
failureMessage.AddText(" failed: ");
failureMessage.AddExpression(e.Message);
Console.WriteLine(failureMessage.ToValue());
throw;
}
}
To finish off we also need to make a small adjustment to our BuildInterpolatedString method to take our new IsSensitive Boolean into consideration.
private static InterpolatedStringBuilder BuildInterpolatedString(bool includeOutParameters)
{
var stringBuilder = new InterpolatedStringBuilder();
// Include the type and method name.
stringBuilder.AddText(meta.Target.Type.ToDisplayString(CodeDisplayFormat.MinimallyQualified));
stringBuilder.AddText(".");
stringBuilder.AddText(meta.Target.Method.Name);
stringBuilder.AddText("(");
// Include a placeholder for each parameter.
var i = meta.CompileTime(0);
foreach(var p in meta.Target.Parameters)
{
var comma = i > 0 ? ", " : string.Empty;
if(SensitiveParameterFilter.IsSensitive(p))
{
// Do not log sensitive parameters.
stringBuilder.AddText($"{comma}{p.Name} = <redacted> ");
}
else if(p.RefKind == RefKind.Out && !includeOutParameters)
{
// When the parameter is 'out', we cannot read the value.
stringBuilder.AddText($"{comma}{p.Name} = <out> ");
}
else
{
// Otherwise, add the parameter value.
stringBuilder.AddText($"{comma}{p.Name} = /\{\{/");
stringBuilder.AddExpression(p.Value);
stringBuilder.AddText("}");
}
i++;
}
stringBuilder.AddText(")");
return stringBuilder;
}
Rebuild the Metalama.Logging project.
Return to the console project and amend the Strings class and the main method and then run it.
internal static class Strings
{
[Log]
public static void Login(string username, string password) { Console.WriteLine("This is the Login Method"); }
[Log]
public static void MyNewLogin(string username, [NotLogged] string secret)
{ }
}
static void Main(string[] args)
{
try
{
//Calculator.Add(1, 1);
//Calculator.Subtract(2, 1);
//// the following will report infinity as the result as we are dealing with doubles
//Calculator.Divide(2, 0);
////the following will report a Divide by zero exception as we're dealing with integers
//Calculator.DivideInt(2, 0);
Strings.Login("dom", "mySuperSecretPassword");
Strings.MyNewLogin("dom", "mySuperSecret");
}
catch
{
}
}
Strings.Login(username = {dom}, password =
This is the Login Method
Strings.Login(username = {dom}, password =
Strings.MyNewLogin(username = {dom}, secret =
Strings.MyNewLogin(username = {dom}, secret =
Now that is much better, and implementation to protect sensitive data will be easy. However, I’m a naturally lazy individual and as I don’t touch type the mere thought of having to add a [Log] attribute to every method in every class that I want to be logged fills me with dread. Surely there’s an easier way? As luck would have it there is. Metalama has a little magic trick up it’s sleeve that it calls Fabrics. Essentially these are relatively small bits of code that we can write to weave code into our target project(s).
Adding a Fabric to make life even easier
Return to your Metalama.Logging solution and add a class called Fabric to it containing the following code.
public class Fabric : TransitiveProjectFabric
{
public override void AmendProject(IProjectAmender amender)
{
amender.Outbound
.SelectMany(compilation => compilation.AllTypes)
.Where(type => type.Accessibility is Accessibility.Public or Accessibility.Internal)
.SelectMany(type => type.Methods)
.Where(method => method.Accessibility == Accessibility.Public && method.Name != "ToString")
.AddAspectIfEligible<LogAttribute>();
}
}
There’s quite a lot going on here and it will pay us to discuss it in a little more detail.
The Metalama documentation describes a Fabric as ‘a class that, when inherited by a type in a project (under any name or namespace), allows that type to analyse and add aspects to that project’. Whilst that description is technically accurate it may not be entirely obvious to the reader what is actually being described here.
Our Metalama.Logging project has been designed with a view to allowing other projects and solutions that we create in the future to inherit it and thus provide that magic ingredient that is Metalama logging. Fabrics take that magic a little further. When we add a Fabric to our Logging project and that project is in turn referenced by other projects, those projects will at compile time, be able to to be amended by the Fabric.
Returning to the fabric that we have just created. It inherits from TransitiveProjectFabric (so it will be applied to multiple projects in their entirety. We are required to override the AmendProject() provided by the ProjectFabric and in so doing we will instruct the fabric as to what we want it to do to the projects that it has access to.
In this particular case we are instructing the Fabric to select all items in our project that are Methods and have a ‘public’ signature and whose name isn’t equal to ‘ToString’. We need to avoid logging ToString methods because doing so could cause an infinite recursion.
We are then saying that if there are methods in our project that meet the criteria that we have specified then the Fabric should go ahead and add the [Log} attribute to those classes. If you’ve grasped the significance of what has just been described then you’ll already have some idea of just how powerful Fabric’s can be.
Now rebuild the Metalama.Logging project and when that is done return to the console project. We’ll add two new classes to this (NewCalculator and NewStrings) and in each we’ll replicate the methods that we added in their previous incarnations, only this time we’ll not add the [Log] attribute to them. Amend the Main method to call your new classes (taking care to comment out the Calculator.DivideInt method as calling that early on will terminate the app as we designed the method to throw an error). If all goes well you see numerous new log entries from classes and methods that you haven’t had to manually edit with the [Log] attribute.
This alone should be sufficient to prove to you just how powerful Metalama is and what a time saver it can be. There is one more benefit which might just have slipped your attention. Your main application code is EXACTLY as it was. If you save it to a code repository like GitHub you’ll just be saving your code. It remains easily readable and its intention is still clear as there is no boiler plate code for you to negotiate your way around.
Conclusion
As we have just seen, simple informative logging is easily achievable with Metalama and for relatively little effort on your part (even less if you make use of the Nuget package that goes with this pamphlet!). If you’re not logging comprehensively (at least in the development stage) then you’re doing yourself a disservice and making any debugging that you have to do that much more difficult.
Adding Complexity to Logging
Thus far we’ve looked at implementing some very simple straightforward logging to a project and in the process seen that we can return a wealth of information about what is actually happening in our code. Let’s start to add some useful bits and pieces into the mix.
Timing
There are occasions when knowing just how long it’s taking for something to happen can prove to be really useful and adding such a facility to our Log aspect is in fact relatively straight forward. However there is a cost involved in timing everything and frankly there are really only certain areas (getting information from an external service for example) where knowing how long the operation took might prove to be useful.
This is, arguably, something that the developer writing the code in the first place ought to know and therefore it’s reasonable to argue that asking them to specifically add an attribute to that one piece of code is not really that onerous a job. Given that we’ll create a separate logging aspect to providing a record of how long a method took to run, as well as all the other information we are currently collecting.
In the Metalama.Logging project create a new class called TimedLogAttribute which, just as with the original LogAttribute, will inherit from OverrideMethodAspect. To start with copy and paste the code inside your Log Attribute to this class (omitting the interpolatedStringBuilder). You’ll see an immediate error with the call to BuildInterpolatedString which we’ll rectify by moving that method to a static helper class so that we don’t have to constantly repeat it. You’ll need to decorate your helper class with the [CompileTime] attribute.
With that done we’ll make a couple of small changes to our new TimedLogAttribute.
public class TimedLogAttribute : OverrideMethodAspect
{
public override dynamic OverrideMethod()
{
// Write entry message.
var entryMessage = LogHelpers.BuildInterpolatedString(false);
entryMessage.AddText(" started.");
Console.WriteLine(entryMessage.ToValue());
//add a means to time the method's execution
var stopwatch = new Stopwatch();
stopwatch.Start();
try
{
// Invoke the method and store the result in a variable.
var result = meta.Proceed();
// Display the success message. The message is different when the method is void.
var successMessage = LogHelpers.BuildInterpolatedString(true);
if(meta.Target.Method.ReturnType.Is(typeof(void)))
{
// When the method is void, display a constant text.
successMessage.AddText(" succeeded.");
}
else
{
// When the method has a return value, add it to the message.
successMessage.AddText(" returned ");
//check to see if we are dealing with sensitive data
if(SensitiveParameterFilter.IsSensitive(meta.Target.Method.ReturnParameter))
{
successMessage.AddText("<redacted>");
}
else
{
successMessage.AddExpression(result);
}
successMessage.AddText(".");
}
Console.WriteLine(successMessage.ToValue());
return result;
}
catch(Exception e)
{
// Display the failure message.
var failureMessage = LogHelpers.BuildInterpolatedString(false);
failureMessage.AddText(" failed: ");
failureMessage.AddExpression(e.Message);
Console.WriteLine(failureMessage.ToValue());
throw;
}
finally
{
//we need to know how long all of this took
stopwatch.Stop();
var elapsedMessage = LogHelpers.BuildInterpolatedString(false);
elapsedMessage.AddText(" elapsed: ");
elapsedMessage.AddExpression(stopwatch.ElapsedMilliseconds);
elapsedMessage.AddText("ms");
Console.WriteLine(elapsedMessage.ToValue());
}
}
}
It should be pretty obvious what is going on here so once you’ve made these changes go to the Fabric class and change
Add the following method to the LogAttribute Class.
public override void BuildAspect(IAspectBuilder<IMethod> builder)
{
if(!builder.Target.Attributes.OfAttributeType(typeof(TimedLogAttribute)).Any())
{
builder.Advice.Override(builder.Target, nameof(this.OverrideMethod));
}
}
In essence we are ensuring that the LogAttribute will not be added to any Methods that are already decorated with our new [TimedLog] attribute.
Go back to the Fabric class and reverse the previous adjustment that you made there and now rebuild your Metalama.Logging project.
Return to your console project and very specifically add a [TimedLog] attribute to one of the methods therein. Build and run the application. Notice that all but the one method to which you added the [TimedLog] attribute are returning logs without timing info (so we know that they are being decorated with the [Log] attribute by the Fabric. However the one method that we manually added the [TimedLog] attribute to is providing additional information to the log about how long it took to execute.
Debug versus Runtime Logging
Thus far we have been concentrating our efforts on producing comprehensive logs that will provide us as developers with as much information as possible whilst we actually develop our applications (which we will typically be doing in debug mode). Naturally we all like to think that we write bug free and hence exception free code but the harsh reality is that we don’t. It’s inevitable that some errors will make it to release mode. It would be really useful to have those logged but avoid logging all the extra stuff that went into our logs during development. Metalama provides a way for us to do that.
Lets amend our BuildAspect method in the LogAttribute Class.
public override void BuildAspect(IAspectBuilder<IMethod> builder)
{
if (!builder.Target.Attributes.OfAttributeType(typeof(TimedLogAttribute)).Any())
{
if (builder.Target.Compilation.Project.Configuration == "Debug")
{
builder.Advice.Override(builder.Target, nameof(this.OverrideMethod));
}
else
{
builder.Advice.Override(builder.Target, nameof(this.CondensedOverrideMethod));
}
}
}
Notice that we are now adding an additional condition to check for the actual build configuration. If it’s a debug build we’ll go on to use the original OverrideMethod to add the code we want added to log in detail, but if it’s release we use an alternative method to provide some slimmed down logging.
[Template]
public dynamic CondensedOverrideMethod()
{
try
{
// Invoke the method and store the result in a variable.
var result = meta.Proceed();
return result;
}
catch(Exception e)
{
// Display the failure message.
var failureMessage = LogHelpers.BuildInterpolatedString(false);
failureMessage.AddText(" failed: ");
failureMessage.AddExpression(e.Message);
Console.WriteLine(failureMessage.ToValue());
throw;
}
}
If you do some experimentation in your Console project (having obviously first rebuilt your Metalama.Logging project) and switch between running Debug and Release builds you’ll immediately notice the difference in what is actually logged.
In reality taking this approach with logging is probably not the best idea. What is really needed is a way to switch logging levels at runtime and we will cover that a little later on but this exercise has served to illustrate the control that you can bring to the code that Metalama will generate on your behalf.
Real World Logging with Metalama
Now that we have seen what we can do let’s actually refine this into a real world example that can be used.
All of the code examples that follow are contained within an online public GitHub Repository and the class libraries that are discussed will be available on Nuget.
This means in effect that you have no need to actually create these libraries on your own, however if you do you should in reality gain form the experience because it will broaden your knowledge about how Metalama works and how you could use it to make your own day to day programming that bit easier.
As the libraries are the main source for this document the actual Nuget Packages will not be available until work on this document and by extension the supporting code is complete. As soon as they are available though links to them will appear just below here.
The Nuget package is available here.
Introduction
Logging directly to the console window, as we have done up to now, if fine for development work and where the logging being done is relatively minor.
That though is unlikely to be the case. Logs provide an invaluable tool in the debugging process and in reality, especially during the development phase, developers will want to log as much information about their application as they can.
This is where Logging Frameworks come into their own.
We’ll start by using The ILogger interface and as we will find out in due course it will allow us to easily substitute a Logging Framework of our own choice.
The code that we’ll be discussing can be found in the Vtl.LogToConsole project in the repository. The principles that we’ll apply are much as we’ve already discussed but refined in such a way as to make them better fit the structure of a class library created with reuse in mind.
The class libraries you’ll find in the repository are all built on .Net Standard 2.0. This offers the greatest flexibility for using them against both .Net Framework and .Net Core applications. The test apps included are themselves based on .Net Core (6.0).
The test application is just a simple console app and once again logging will be directed to the console but it will illustrate the basics well and provide a firm building block.
ILogger
If you’re familiar with the ILogger interface provided by Microsoft.Extensions.Logging (available through NuGet) then you can skip this section but if ILogger is new to you then it is worth you learning a little about it first.
There is a wealth of documentation within microsoft’s own documentation site but this can be a little dry.
If you want a slightly more down to earth explanation of what it is and why it’s worth using then Tim Corey produced an excellent video on YouTube that explains the basic principles very well.
In essence what ILogger brings to the table is both a way to make use of some extensive logging capabilities that Microsoft has itself already baked into .Net but it rather neatly opens to door for you, the developer, to then substitute a logging Framework of your own choice to provide logging, opening up the possibility of logging to a range of different places and also creating structured logs.
It should be noted that Microsoft’s ILogger does itself provide structured logging but in reality providers like Serilog tend to do it a litter more comprehensively.
Using ILogger will require a reference to it in every single class that we want to log. There are basically two ways of doing this.
The first is manually. That would require that we add, at the very least, the following to each and every class that we create.
internal class TestClass
{
private readonly ILogger<TestClass> logger;
public TestClass(ILogger<TestClass> logger)
{
this.logger = logger;
}
}
This implies that we would probably need some sort of check that this is present at the point that we add our [Log] attribute to provide logging.
We could on the other hand use Dependency injection to do this.
There are two good basic examples of how to do this in the MetaLama Samples. Take a look specifically at Log Samples 4 and 5. Notice how sample 5 provides some examples of Diagnostic verification that you can add to aspects to ensure that they are used correctly.
I personally chose to go down the Dependency Injection route, but either approach is perfectly acceptable.
There is one point that you should note carefully. ILogger can’t be used in Static Classes as they don’t have a constructor and by extension no means to introduce the ILogger, either manually or via Dependency Injection.
This means that you will need to ensure that end users of the class library know that they won’t be able to log static classes (and obviously any static methods that they contain) with any class Library that you provide that utilises ILogger.
You can find reference by doing searches on the internet, to ways that you could circumvent this. This isn’t the place to discuss such approaches but we will cover how to avoid automatically adding the attribute to static methods when using a Fabric to cover a project.
Sensible Naming and Documentation
This may seem blindingly obvious but by considering the names that you apply to the various aspects that you create you will make it much more apparent to the end user what it is that they are;
- Intended to do.
- Where they are meant to be applied.
It also makes good sense to document the aspects that you create thus providing your end users with some useful help via intellisense.
Points of Interest
With that said let’s look at some of the points of Interest arising from applying some real world implementation to the basics of the simple logging discussed earlier.
Attributes / Aspects
These have been renamed so that it is abundantly clear from their names exactly what they are intended to do.
Sensitive Parameters
We had mentioned earlier that there might be some merit to having a slightly more dynamic approach to the collection of parameter names to search for and this Class Library implements one such approach.
The inspiration for this came from the Documentation itself, see here. This is not the easiest of concepts to follow but if you read the file referred to in the documentation then the additional files that you see in the repository will make sense. The ultimate goal of this is that the end user will add a text file ‘Sensitive.txt’ at the root of their project / solution containing names to search on an apply a redacted log entry to.
Fabric Extensions
Rather than provide a specific fabric the library instead provides a number of extension methods each of which can be called in the end user’s own Fabric.cs. Each extension method has been named in such a way as to make it obvious what it actually does. These are worth looking at as they illustrate some of the ways in which you can configure a fabric to search out those classes and methods to which you want your attributes to be applied.
It is worth noting, as we are using ILogger that all of the provided extension methods specifically exclude static classes from the classes that will have considered. You can see that this is specifically stated in the comments for each method, and done this way that remark will appear in intellisense as well when the ned user gets to call your extension method.
Also note that any method named ‘ToString’ is also specifically excluded, this is to avoid a recursive call.
///---- LogAllMethods (Method) ----
///
/// <summary>
/// An IProjectAmender extension method that logs all methods.
/// </summary>
///
/// <remarks>Specifically excludes methods from Static classes.</remarks>
///
/// <param name="amender">The amender to act on.</param>
///-------------------------------------------------------------------------------------------------
public static void LogAllMethods(this IProjectAmender amender)
{
amender.Outbound
.SelectMany(compilation => compilation.AllTypes)
.Where(type => !type.IsStatic)
.SelectMany(type => type.Methods)
.Where(method => method.Name != "ToString")
.AddAspectIfEligible<LogMethodAttribute>();
}
///---- LogAllPublicAndPrivateMethods (Method) ----
///
/// <summary>
/// An IProjectAmender extension method that logs all public and private methods.
/// </summary>
///
/// <remarks>Specifically excludes methods from Static classes.</remarks>
///
/// <param name="amender">The amender to act on.</param>
///-------------------------------------------------------------------------------------------------
public static void LogAllPublicAndPrivateMethods(this IProjectAmender amender)
{
amender.Outbound
.SelectMany(compilation => compilation.AllTypes)
.Where(type => type.Accessibility is Accessibility.Public or Accessibility.Internal && !type.IsStatic)
.SelectMany(type => type.Methods)
.Where(method => method.Accessibility is Accessibility.Public or Accessibility.Private &&method.Name != "ToString")
.AddAspectIfEligible<LogMethodAttribute>();
}
///---- LogAllPublicMethods (Method) ----
///
/// <summary>
/// An IProjectAmender extension method that logs all public methods.
/// </summary>
///
/// <remarks>Specifically excludes methods from Static classes.</remarks>
///
/// <param name="amender">The amender to act on.</param>
///-------------------------------------------------------------------------------------------------
public static void LogAllPublicMethods(this IProjectAmender amender)
{
amender.Outbound
.SelectMany(compilation => compilation.AllTypes)
.Where(type => type.Accessibility is Accessibility.Public or Accessibility.Internal && !type.IsStatic)
.SelectMany(type => type.Methods)
.Where(method => method.Accessibility is Accessibility.Public && method.Name != "ToString")
.AddAspectIfEligible<LogMethodAttribute>();
}
This will allow your end user to create their own Fabric.cs class and either use one of your extensions or alternatively create their own fabric from scratch.
internal class Fabric : ProjectFabric
{
public override void AmendProject(IProjectAmender amender)
{
amender.LogAllPublicMethods();
}
}
Structured Logging
Now the time has come to look at structured logging.
Up to now the information that we’ve been getting back has just been plain text. It’s readable, it’s informative but it’s a nightmare to actually search efficiently and when it comes to interrogating to find out if there’s a problem or where the problem is or derives from then the ability to search those logs efficiently really comes into its own.
Essentially structured logging generates logs in more easily parsable formats such as XML or JSON. Logs become easier to query, filter or group and accordingly the information that can be derived from them is greatly enhanced. Structured logs are basically Structured Data
What we would like to be able to do though is provide ourselves with a choice to either output text based logs easily readable in the console or fully structured logs that we can easily iterate over in something like SEQ. We’ve seen how easy it is to implement the ILogger interface with Metalama and the vast majority of Logging frameworks can make use of that basic implementation by way of simply swapping the logging framework provide during application startup.
A small problem
Unfortunately though there is one small problem that needs to be looked at. Up until now we have been making use of an Interpolated String Builder to produce the entries that get logged.
This is ideal for text based stuff but if we want to really gain from structured logging then we need the actual values that the entries are referring to and that means using a formatted string rather than an interpolated one. This suggests that we will probably need to provide a different logging aspect for each logging framework that we want to support and indeed that is precisely what PostSharp has done in the past with its different logging provider backends.
It would be great if a way could be found to satisfy the requirements of both at the same time.
Well it turns out that there is a way to do this and it comes to us by way of the InterpolatedStringHandler a new feature of C# 10. There are a few articles to be found on this new feature and the one that really opened my eyes to the possibility was this one. The concept is, like all the best ideas are, simple. Take and interpolated string, a feature that developers are now all too familiar with and use more often than string.Format() but handle it as if it was a formatted string. Now we have the possibility of creating log messages that will work well as text and equally well as structured data. Combine this with the ease with which we know we can use the ILogger interface and we our goal of one logging aspect that can be used with any logging framework, structured or not, is a very real possibility.
Credit where credit is due. Pahan Menski has come up with a very straightforward way to adapting the InterpolatedStringHandler to the ILogger interface. Essentially this is done by creating an Interpolated String Handler for each type of Log entry supported by the Microsoft Extensions Logging ILogger and once that has been done a number of extension methods for the actual message creation that will call these handlers to produce the log entries. Now we can create an interpolated string based message but have the handler provide a text interpretation that can support structured data.
I chose to follow the example presented in the blog post and use T4 text templates to construct the handlers and extension methods. Whilst not strictly necessary this method of working has the advantage od producing well formatted code quickly and easily and eliminates the very real possibility of introducing the small but inevitable typos that so often get into code that has to be written over and over again with small but subtle variations.
Log Levels
Logging Frameworks assign their messages to certain prescribed levels. By doing this it is easier for the reader of those logs to determine what is actually going on and crucially, they provide a means of very quickly filtering what messages actually get written to a log in a production application.
The Microsoft ILogger has six log levels (provided via an enumeration) which are:
- Trace
- Debug
- Information
- Warning
- Error
- Critical
- None
Logging Frameworks that extend the ILogger tend to emulate these levels, but occasionally with different names. Serlog for example has the following;
- Verbose
- Debug
- Information
- Warning
- Error
- Fatal
Essentially the same as ILogger but with a slight change in name for the first and last. In fact internally Serilog maps the two but we do need to be aware of the differences particularly when configuring the actual framework that we intend to use.
A working example
So much for the theory what about putting it into practice. You can find a working example of using an Interpolated StringHandler with a Metalama Log aspect in one of my GitHub repositories here.
In the repository there is a simple proof of concept example based on the Tutorial that Microsoft themselves provide in their own documentation about this new C# feature. There is also a more detailed example proof of concept (very much based on the excellent work done by Pahan Menski) which uses a log aspect written with Metalama.
The Log Aspect itself should be pretty familiar to you by now but it is worth pointing out that you’ll not see the InterpolatedStringBuilder being used. Instead we are creating interpolated string messages within the aspect itself and then using one of the provided log extension methods to write out the message.
Finally you’ll find a simple console application to test the log aspect and if you look in the static main method there are implementations provided to write logs using either the Microsoft ILogger or Serilog.
Note that you will need to reimplement certain usings depending upon which you choose to use.
The console application also demonstrates configuring Serilog via an external appsettings.json file.
Configuring Serilog via ‘appsettings.json’
It would be remiss not to mention in passing the benefits to be gained from actually configuring Serilog via an external configuration file and to look at how we might do that.
The first and most obvious benefit is the fact that you can actively change the configuration settings in a runtime production environment. This provides you with the ability to set the default logging level to something like Warning or Error to reduce the mass of Log entries that might otherwise be produced but equally to turn on more verbose logging when it would be really useful to glean more information about what is actually going on.
The second benefit comes from the multitude of ways that serilog allows you to actually configure the output, especially if you start to add some of the additional Nuget packages that have been created to do just that.
Adding the appsettings.json
The GitHub solution that is demonstrating this has a simple .Net 6 console App to show show off the Metalama class library. We need to configure that to read the the external file. To make that possible I added the Microsoft.Extensions.Hosting NuGet Package along with the Serilog.Extensions.Hosting and Serilog.Settings.Configuration packages.
This will allow me to add the following code to the static Main entrypoint.
var builder = new ConfigurationBuilder();
BuildConfig(builder);
Log.Logger = new LoggerConfiguration()
.ReadFrom.Configuration(builder.Build())
.CreateLogger();
which references the following, also added to the Program.cs file.
static void BuildConfig(IConfigurationBuilder builder)
{
builder.SetBasePath(Directory.GetCurrentDirectory())
.AddJsonFile("appsettings.json", optional: false, reloadOnChange: true)
.AddJsonFile(
$"appsettings.{Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") ?? "Production"}.json",
optional: true)
.AddEnvironmentVariables();
}
Essentially what’s happening here is that the BuildConfig method is determining where the application resides and then sets about adding the main appsettings.json file to the configuration.
Note that you are not restricted to a single app settings file which opens up the possibility to configure things differently for different environments.
With the settings file having been made known to the ConfigurationBuilder it’s possible to then go on and create the Logger. Currently that will still use the default Microsoft Logger. We can now change that. Add the following below the code you added to the static Main method.
var host = Host.CreateDefaultBuilder()
.ConfigureServices(
services =>
{
services.AddTransient<Calculator>();
})
.UseSerilog()
.Build();
Now all we need is the Json file itself.
Add a new appsettings.json file to the project. in it’s properties set the Copy to Output Directory to Copy always
The Serilog section in the ‘appsettings.json’ file
A very basic Serilog section will have the following elements.
{
"Serilog":
{
"Using":[],
"MinimumLevel": ,
"WriteTo":[],
}
}
To get a full appreciation of just what you can do with this it is well worth consulting the Serilog Documentation. This is a complex topic and as aluded to earlier there are a myriad of ways that Serilog can be configured. My best advice is to experiment and find what works best for you. Just bear in mind that you can create different configurations for each sink that you write to.
Putting everything together
Finally we can put what we’ve learned to use and create something useful.
Log Guard
It is conceivable that a recursive loop could be triggered in certain logging scenarios which is something that should be avoided so the actual finished package also contains a recursion guard
Nuget
VtlSoftware>Logging is available on Nuget.
It can be installed via the .Net Cli with the following command
dotnet add package VtlSoftware.Logging --version <xxx>
Or Via the Nuget package manager with the following command.
NuGet\Install-Package VtlSoftware.Logging -Version <xxx>
Testing
VtlSoftware.Logging is also backed with it’s own public GitHub repository. Within the GitHub repository you’ll find not only the VtlSoftware.Logging project that is the substance of the Nuget Package but you’ll also find a test project as well that tests as many of the differing ways that the aspects might be applied as I could think of.
I can’t stress highly enough the importance of testing your aspects. Testing the logging project exposed a flaw that I had omitted to cater for. You can find out more about how to test aspects in the Metalama Documentation
Documentation
The Nuget package is also fully documented. Good documentation is a subject I’m passionate about so it behoves me to try and make sure that I follow my own advice in this regard.
Versioning
The plan is that the logging library will mirror the version numbers of the latest available GA release of Metalama itself.
A final note about Licencing
It should be possible to use this library free of charge. It should consume no more that one credit and the Free edition of Metalama allows you up to three credits.