Today let’s talk about logging.
Several years ago, when writing a C# based domain specific language and framework for transforming electronics product specification (I should definitely blog about it some time later) as well as runtime infrastructure for it, I was faced with a problem : easy operation logging. By operation logging I mean logging messages upon operation start and after its end.
The easiest way is to write just two messages, one before some DoWork() method call and the second one after it.
Which gives us something like this.
Log.Information("Started Operation");
DoWork();
Log.Information("Finished Operation");This looks easy, bulletproof and readable. But we certainly can do better.
- First of all, the message is somewhat duplicated, since the only thing that changes is the operation name, and both
StartedandFinishedare the static parts. - Second – the overall call to
Log.Information()always stays the same, making it a boilerplate which is not much fun to write. - Third – message structure. Almost all common structured logging frameworks use message templates and parameters that are supplied along with it to render the final message.
- Fourth – reporting. We might want to report some operation results after the operation completes.
- Fifth. If reporting then, as an added bonus, why don’t we measure the operation duration. This is not a precise benchmark, of course, but the rough estimate can also be very useful during development and debugging.
- Last but not least – integration. We might want to use some other logging framework, even during the app development cycle. This will require us to change the call itself, sometimes significantly.
Let’s start with removing duplication and boilerplate.
This can easily be done using (pun intended) C# dispose pattern. Strictly speaking, it’s not designed for such scenarios, but hey, let’s try and see what happens.
class Reporter : IDisposable
{
private string _actionDescription;
private ILogger _logger;
public Reporter(ILogger logger, string actionDescription)
{
_actionDescription = actionDescription;
_logger = logger;
logger.Information($"Started {operationName}");
}
public void Dispose()
{
_logger.Information($"Finished {_actionDescription}");
}
}Now for the usage.
using (Reporter r = new(logger, "some useful work"))
{
DoWork();
}Great! So now we don’t need to duplicate all the logger calls and messages.
Let’s add some structure shall we?
public Reporter(ILogger logger, string actionDescription, params object[] actionDescriptionParameters)
{
_actionDescription = actionDescription; // message template here
_logger = logger;
_actionDescriptionParameters = actionDescriptionParameters;
logger.Information($"Started {operationNameTemplate}", operationParameters);
}On the caller side.
using (Reporter r = new(logger, "operation {index}", 0))
{
DoWork();
}Neat, structured, still readable and much less boilerplate. We are using object[] to allow supplying whatever the parameters we might have.
Outputting some message when operation completes is as simple as putting another string formal parameter to the Reporter ctor. But what if we want to report on some information, that we have returned from the DoWork() , for example some inserted or read rows count. How can we feed that number into the Reporter ctor before actually knowing it? Well, we can use (or rather abuse?) some of C# functional programming features. Yes you got it correctly, I’m talking about closures here. To not clutter the original Reporter ctor let’s create another one. We’ll get to how can fuse the two later on.
public Reporter(
ILogger logger,
string actionDescription,
string endActionMessageTemplate = null,
params Func<object>[] countProviders)
{
_actionDescription = actionDescription; // message template here
_logger = logger;
_endActionMessageTemplate = endActionMessageTemplate;
_countProviders = countProviders; // closures for getting objects count from within the chronograph scope
logger.Information($"Started {operationNameTemplate}", operationParameters);
}Let’s see how our Dispose() method should behave now.
private void Dispose()
{
var actionDescriptionParameters = _actionDescriptionParameters.ToList(); // defensive copy
if (_countProviders != null
&& _countProviders.Length > 0)
{
var counts = _countProviders.Select(TryInvokeCountProvider).Where(c => c != null);
actionDescriptionParameters.AddRange(counts);
}
string finalTemplate = string.IsNullOrWhiteSpace(_endActionMessageTemplate)
? $"Finished {_actionDescription}"
: $"Finished {_actionDescription}. {_endActionMessageTemplate}";
_logger.Information(finalTemplate, actionDescriptionParameters.ToArray());
}
private object TryInvokeCountProvider(Func<object> provider)
{
try
{
return provider?.Invoke();
}
catch
{
return int.MinValue; // means invoking count provider threw an exception
}
}There are some things screaming for clarification.
First of all, TryInvokeCountProvider() is a basic fail-safe to not throw exceptions from Dispose() method which is generally a bad thing. We can do better in TryInvokeCountProvider but I intentionally simplify the process here.
Second – actionDescriptionParameters.ToArray() call. If we remove the ToArray() all our parameters would be treated as a single one and end up with the first template placeholder rendered as System.Collections.Generic.List'1 and others not rendered at all.
Minor third. There is some field for allocation optimization but I’ll keep it out of this post for brevity reasons.
So now we can invoke our Reporter as follows.
int rowsCount = 0;
using (Reporter r = new(logger, "getting info from the database", "got {rowsCount} rows", () => rowsCount))
{
rowsCount = GetInfoFromDb();
}Nice. Logging and reporting done in just one line of code. There is a catch though. ReSharper will rightfully yell at you with Access to disposed closure inspection. That’s because it sees a lambda closing over an external state (rowsCount variable) in using statement, which is almost always a bad sign. But what it can’t see (yet, I believe) is that we invoke lambda before returning from Dispose method so it seems harmless and we can suppress this warning in our code.
During PR reviews I’m getting rather suspicious when I see someone suppressing diagnostics messages without clarification, so we have a rule : if the suppression required – always describe a reason why did it happen. There are several ways to do this.
Attribute [SuppressMessage("ReSharper", "AccessToModifiedClosure", Justification = "Using only inside Reporter for reporting purposes")] has specialized Justification property.
Simple one time suppression comment // ReSharper disable once AccessToModifiedClosure Justification: Using only inside Reporter for reporting purposes can be extended to include justification message.
Let’s get back to our reporting business. Last thing to add in terms of features is the operation timing. I repeat, that it’s rather a rough estimation than the real precise timing.
public Chronograph(
ILogger logger,
string actionDescription,
string endActionMessageTemplate = null,
params Func<object>[] countProviders)
{
_actionDescription = actionDescription; // message template here
_logger = logger;
_endActionMessageTemplate = endActionMessageTemplate;
_countProviders = countProviders; // closures for getting objects count from within the chronograph scope
logger.Information($"Started {operationNameTemplate}", operationParameters);
_stopwatch = Stopwatch.StartNew();
}
private void Dispose()
{
if (!_stopwatch.IsRunning)
{
// just some nice sanity check
_logger.Warning(
$"Looks like chronograph for operation {{actionDescription}} was not properly initialized or already disposed or stopped. Reported results may be incorrect.",
_actionDescription);
}
_stopwatch.Stop();
var elapsedString = _stopwatch.Elapsed.ToString("g");
var actionDescriptionParameters = _actionDescriptionParameters.ToList(); // defensive copy
if (_countProviders != null
&& _countProviders.Length > 0)
{
var counts = _countProviders.Select(TryInvokeCountProvider).Where(c => c != null).ToArray();
actionDescriptionParameters.AddRange(counts);
}
actionDescriptionParameters.Add(elapsedString);
string finalTemplate = string.IsNullOrWhiteSpace(_endActionMessageTemplate)
? $"Finished {_actionDescription}. [{{operationDuration}}]"
: $"Finished {_actionDescription}. {_endActionMessageTemplate}. [{{operationDuration}}]";
_logger.Information(finalTemplate, actionDescriptionParameters.ToArray());
}Code above is pretty much self-explanatory. Since we are now reporting timings, notice the ctor rename.
As I said it’s an added bonus so the caller side code changes are not required.
Let’s see, duplication removed, structure, reporting and timing added. One downside is that we now have several ctors in play. Let’s resolve this final issue before getting to integration.
In this particular case one of the best approaches would be a fluent builder-ish interface with extension methods on the logger interface itself for ease of use. I won’t bother you with implementation details but what we have in the end looks like this.
int insertedRowsCount = 0;
int updatedRowsCount = 0;
using (var chrono = logger.Chrono().For("operation {operationNumber}", 0)
.Report("{insertedRowsCount} rows inserted, {deletedRowsCount} rows updated",
() => insertedRowsCount,
() => updatedRowsCount)
.WithEventLevel(ChronographLoggerEventLevel.Debug)
.Start()
)
{
(insertedRowsCount, updatedRowsCount) = UpdateInfoInDb();
}Where Chrono() is an extension method on ILogger interface and all other chained methods setting up the Chronograph instance (returning this for fluency) before starting the internal stopwatch. Notice that we now have control over an event level.
Given an amount of action packed into that single using statement all this using abuse looks not so bad after all! We can strip some more chars with using declaration but what we have is good enough as it is.
Now for the last part – abstracting away the concrete logger implementation. First of all let’s extract logger interface that we can lean against (notice the generic ChronographLoggerEventLevel since all the logging frameworks use different names for event levels).
public interface IChronographLogger
{
void Write(ChronographLoggerEventLevel level, string message);
void Write(ChronographLoggerEventLevel level, string messageTemplate, params object[] propertyValues);
}Then implement that using our logging framework of choice. Last step is to add an extension method for chronograph creation to our logging framework core interface. Here’s the example for Serilog.
public static Core.Chronograph Chrono(this ILogger targetLogger)
{
var serilogChronoLogger = new SerilogChronographLogger(targetLogger);
return Core.Chronograph.Create(serilogChronoLogger)
.WithEventLevel(DefaultChronographEventLevel);
}In our final implementation we have a single option to create the Chronograph instance – Chronograph Create(IChronographLogger logger) static factory method.
Conclusion
There is no such thing as a free lunch, same goes for logging. There is always an overhead in terms of allocations and performance, and even more so – with custom chronograph like the one I described above. But sometimes we can sacrifice some CPU cycles and garbage collections in order to have a clean and universal method of reporting operations. And if – after all the benchmarking and profiling – we find out that no we can’t, well, it was fun to design and build anyways!