Avoid Logging in Low-Level Code

In large enterprise codebases, it's really common to build lots of low-level helper methods and classes. Maybe you have a BlobHelper that can upload files to blob storage, and JsonHelper that serializes JSON using your preferred JSON converter settings, or an EncryptionHelper that knows what encryption algorithms you want to use. And possibly some of these have even become NuGet packages of their own to be shared across a few different micro-services.

Most developers have also had it drummed into their heads repeatedly that good code has lots of logging. The more information we have in the logs, the more likely we are to be able to diagnose a problem in production. And so its very common to see lots of logging statements in helper classes like this.

Why you shouldn't log in low-level code

But I'm increasingly finding myself removing logging from classes like this. Here's a few reasons why.

1. It can result in huge volumes of logging of relatively low-value messages. Logging does not come for free either in terms of performance or storage costs. If your system processes 10 million queue messages a day, do you really need millions of log entries saying "about to encrypt message", "about to send message", "sent message", etc?

2. Low-level code cannot intelligently decide what to log. It lacks the context. Maybe sometimes it really matters that we tried to delete a file that didn't exist. But probably most of the time we don't care.

3. Low-level code doesn't know whether data is sensitive or not. If you can't deserialize some JSON, it's really handy to write it to the logs. Except if it contains personal information. In which case you probably shouldn't. But again, a low-level helper class lacks the context to make that decision - it's the consumer that knows.

4. It forces your low-level code to take a dependency on your ILogger interface. This might not seem a big deal, but coupling like this can result in code that is hard to maintain going forwards, especially if you want to reuse it in a context that has a different approach to logging.

5. There are better ways to ensure all useful information gets logged...

How should I support logging from low-level code?

One of the most helpful ways I've found of explaining to developers that their low-level code doesn't need to take a dependency on an ILogger is that all of the NuGet packages that they are using don't. Third party libraries like Newtonsoft, Polly, or Entity Framework, and countless others all manage to work without depending on your logging framework. But how?

Well it's quite simple for errors. They report errors by raising exceptions. And expect the caller to log those exceptions if necessary.

But what about operations that "succeeded", but something interesting happened along the way that you might want to log? For example, an API helper method might successfully call an API, but only after 7 retries - we might want to record that this has happened.

There are two main ways libraries support reporting this additional information. First, by returning richer result objects. A method could return not only the outcome, but additional data that might be relevant for the caller to log.

And the second approach is to allow the consumer to provide a callback function that will notify them of interesting things that they might want to log. The callback should give them enough information to make a decision on whether they need to log or not.

A simple example

Let's see a simple example that will hopefully make a bit more sense of what I'm driving at. Imagine a very simple ConfigHelper class. As you can see, it depends on ILogger, and tries to be helpful by logging when we used a default value because a setting was missing, as well as logging an error condition:

public class ConfigHelper
{
    private readonly ILogger logger;
    private readonly IConfigStore configStore;
    public ConfigHelper(ILogger logger, IConfigStore configStore)
    {
        this.logger = logger;
        this.configStore = configStore;
    }

    public int GetSettingInt(string setting, int defaultValue)
    {
        var configValue = configStore.GetValue(setting);
        if (string.IsNullOrEmpty(configValue)
        {
            logger.Warning($"Config value {setting} missing, using default");
            return defaultValue;
        }
        if (!int.TryParse(configValue, out int value)
        {
            logger.Error($"Invalid value for setting {setting}");
            throw new InvalidOperationException($"Invalid value for setting {setting}")
        }
        return value;
    }
}

Now personally, I'd argue this class doesn’t actually need any logging at all. First of all, the error condition throws an exception, so that is likely getting logged again further up the chain. No need to double log it – just make sure that the exception message is good. In some cases a custom exception type may be a better choice here, as it can add properties that allow the consumer to make decisions based on the associated data.

Secondly, the condition logged as a warning is probably a perfectly normal thing to happen in a real-world. It will just become noise in the logs. So we could just remove the ILogger dependency from ConfigHelper and all would be fine.

But let’s suppose, just for the sake of argument, that it really is useful for us to be able to log if we returned the default value for the config setting. One option is to use richer return objects. Say we define a simple object like this:

public class ConfigSettingInt
{
    public ConfigSettingInt(int value, bool usedDefault)
    {
        Value = value;
        UsedDefault = usedDefault;
    }
    
    public int Value { get; }
    public bool UsedDefault { get; }

    public static implicit operator int(ConfigSettingInt s) => s.Value;
}

That allows us to return an object rich enough that the consumer could log the fact that the default was used. The consumer is better placed to make this decision, because sometimes we might care about this, and sometimes we might not, depending on which particular setting we were retrieving. By pushing responsibility to the consumer, we gain the ability to only log sometimes. (BTW, the implicit operator I added in the example is a nice compiler trick to allow us to treat the method like it returns an integer if that’s all we care about).

So here's an updated ConfigHelper that allows the consumer to decide whether using a default is worth logging or not:

public class ConfigHelper
{
    private readonly IConfigStore configStore;
    public ConfigHelper(IConfigStore configStore)
    {
        this.configStore = configStore;
    }

    public ConfigSettingInt GetSettingInt(string setting, int defaultValue)
    {
        var configValue = configStore.GetValue(setting);
        if (string.IsNullOrEmpty(configValue)
        {
            return new ConfigSettingInt(defaultValue,true);
        }
        if (!int.TryParse(configValue, out int value)
        {
            // consumer can log this
            throw new InvalidOperationException($"Invalid value for setting {setting}")

        }
        return new ConfigSettingInt(value,false);
    }
}

Sometimes making a custom return object feels like overkill, but we’d still like the consumer to be able to hook in to log interesting events if they want to. So another simple approach is allowing a callback to be injected (or alternatively, raise an event). So in this simple example, you can provide your own callback:

public class ConfigHelper
{
    private readonly IConfigStore configStore;
    public ConfigHelper(IConfigStore configStore)
    {
        this.configStore = configStore;
    }
    
    public Action<string> UsedDefaultCallback { get; set; }

    public int GetSettingInt(string setting, int defaultValue)
    {
        var configValue = configStore.GetValue(setting);
        if (string.IsNullOrEmpty(configValue)
        {
            UsedDefaultCallback?.Invoke(setting);
            return defaultValue;
        }
        if (!int.TryParse(configValue, out int value)
        {
            throw new InvalidOperationException($"Invalid value for setting {setting}")
        }
        return value;
    }
}

This keeps the public interface simple, and keeps the low-level class from depending on a logger, but allows the consumer to make an intelligent decisions on when to log like this:

// initialize the helper to log in certain circumstances
configHelper.UsedDefaultCallback = s =>
{
    if (s.EndsWith("Timeout") 
        logger.Warning($"Config is missing the timeout value for {s}");
};
// ...

var myTimeout = configHelper.GetSettingInt("SomeTimeout",300);

Summary

In summary the benefits of these approaches to keeping ILogger dependencies out of low-level helper or utility code are

1. Avoids the logs getting flooded with unimportant messages
2. Allows the consumer to intelligently decide which events are worth logging, and at what level
3. Prevents the low-level class from taking a dependency on a specific ILogger, which keeps it nicely decoupled

Of course, as an image that has been going round Twitter a lot recently reminds us, in software, the answer is always "it depends". Maybe your low-level code really does need to write its own log messages. But I think that most of the time, it shouldn't.

Next up #ndcsydney, room 4, the talk that contains the slide that got 160+ likes and 60+ retweets and why am I putting pressure on myself oh god pic.twitter.com/tHbY6rS8TW

— David Wengier (@davidwengier) September 21, 2018