Console logging and the passage of time

I frequently write console applications to automate things that I used to do manually. Sometimes these are test frameworks for my own use, other times they are utilities that I share.

In order to know what the tools are doing, it’s important that they generate output that’s readable and straightforward to interpret. After all, there is no point in creating a dedicated tool if all the potential time saving is spent on interpreting the output.

To this end, I have a reusable library for console logging. It’s very simple, perfect for small tools where a proper logging framework would be overkill.

Here’s a sample of output:

Every log message is output with a timestamp on the left. This is invaluable for longer running processes, as I can context switch to a different activity and then evaluate what happened when I return to that console window later on.

Note how the timestamp column is somewhat sparse - it doesn’t repeat parts that haven’t changed between log lines. Where there are many log lines within the same minute, or even the same second, much of the timestamp is elided.

Omitting parts of the timestamp like this gives the column a natural shape - much like the hatch marks you see on a ruler:

You can see the passage of time in the regular ticks, as each second and minute passes.

But, wait, there’s more …

… if you copy and paste from the log, what do you get?

[15:20:20.589] -----------------------------------
[15:20:20.600]   Niche.CommandLine.Demo v1.0.0.0
[15:20:20.601] -----------------------------------
[15:20:20.632] - Configured foreground: Black
[15:20:20.638] - Waiting for ~980ms
[15:20:21.620] - Waiting for ~102ms

The copied lines have the full timestamp!

This isn’t a complicated trick - the elided parts of the timestamp are still printed to the console, but reusing the terminal background colour as the text colour.

private void WriteTimestamp()
{
    var now = DateTimeOffset.Now;
    var color = ConsoleColor.Gray;

    Console.ForegroundColor = color;
    Console.Write('[');

    if (_options.HasFlag(ConsoleLoggerOptions.UseHatchMarksForTime))
    {
        Console.ForegroundColor = Console.BackgroundColor;
    }

    WritePart($"{now:HH}", _lastLogged.Hour, now.Hour);
    WritePart($":{now:mm}", _lastLogged.Minute, now.Minute);
    WritePart($":{now:ss}", _lastLogged.Second, now.Second);

    Console.ForegroundColor = color;
    Console.Write($".{now:fff}] ");

    _lastLogged = now;

    void WritePart(string part, int lastValue, int value)
    {
        if (lastValue != value)
        {
            Console.ForegroundColor = color;
        }

        Console.Write(part);
    }
}

This is a good example for where a local function can simplify a method significantly.