3

It can sometimes ease readability to "draw" lines in a logfile. For example:

noise
noise
----------------------------- Starting Operation ABC
blabla
blabla
----------------------------- End of Operation ABC
noise
noise

Obviously, this should be used sparingly (otherwise the lines don't stand out or sections could overlap). But it can be useful if you're scrolling through a lot of logs, because it tends to stand out.

Is this an anti-pattern? Are there best practices for this sort of thing?

  • 4
    Over the paper looks nice and readable, once in production with several threads writing logs like there were not tomorrow, you will find these practices irrelevant. Better do format the output so that it can be mined by other systems. – Laiv Nov 12 '18 at 10:59
  • It is best to design the log file as a data-based information source. It would take 1 hour to create a nice viewer for the log file or use a standard format such as CSV for contents. Unless you do this, you will have to add visual effects that will complicate the code and prevent serious data queries on the log. The above applies to important logs. Non-important logs and short temp. logs are of no big deal anyway. – NoChance Nov 12 '18 at 14:25
6

At the point where you are considering such visual log file markers, you usually need one of two approaches:

  • You may want better log filtering, e.g. by log level or by component. Instead of searching for specific messages, only output relevant messsages. E.g. you may want to run most of the software with a WARN log level but show one component with a DEBUG log level.

  • You may want machine-readable log records. You can then write a simple script to extract relevant log events – no more scrolling until something pops out. Unfortunately most log files are not machine readable but use an ambiguous ad-hoc format, especially with regards to how line breaks and per-record metadata are handled. It may be worth considering writing the logs to a database than to a flat file.

The major problem with adding visual markers to “important” messages is that importance is context-sensitive. What is important now might be irrelevant tomorrow. Over time, many vaguely important-ish messages will contest for your attention. rendering these marks detrimental.

  • 1
    Yes, this. Are you logging for debug purposes or are you logging for normal operations? Debug for a particular issue may warrant a visual marker, which is removed when issue resolved. Normal operations never. Consider what logging system is being done from the sysadmin's side - syslogd already prefixes w/ date/time, service name, etc for example. Consider a listing of error codes, start your log messages with those (or end with) so there is a well-documented easy to grep for string for each cause of output. – ivanivan Nov 18 '18 at 19:44
1

As far as development (and your direct question) goes, this can't be an anti-pattern as log file content isn't a programming pattern to begin with.


Doing it your way

The main problem with the dashlines you're using is that log writers will be competing with one another.

How are you going to handle nested lines? They should increment in size, but how do you expect the inner logic to be aware of how deep it is situated? How are you going to handle a single piece of logic that for log file A is on the second nesting level, but for log file B is on the fourth nesting level?

You're going to end up tightly coupling your code as each module needs to know where it fits in the big scheme of things; which inherently breaks your encapsulation among other things.

If you want to do this, you're going to have to create a logging class that can handle indentation. A basic example:

public class IndentedLogger
{
    private readonly string filepath;
    private readonly string indentationSegment;
    private readonly int indentationLevel;
    private readonly string indentationLine;

    public IndentedLogger(string filePath, string indentationSegment, int indentationlevel = 1)
    {
        this.filePath = filepath;
        this.indentationSegment = indentationSegment;
        this.indentationLevel = indentationLevel;

        var sb = new StringBuilder();
        for(int i = 0; i < indentationLevel; i++)
        {
            sb.Append(this.IndentationSegment);
        }
        this.indentationLine = sb.ToString();
    }

    public void WriteMessage(string message)
    {
        File.AppendAllText(this.filePath, $"{message}{Environment.NewLine}");
    }

    public void WriteIndentedMessage(string message)
    {
        File.AppendAllText(this.filePath, $"{indentationLine}{message}{Environment.NewLine}");
    }

    public IndentedLogger Next()
    {
        return new IndentedLogger(
                         this.filePath, 
                         this.indentationSegment,  
                         this.indentationLevel + 1);
    }
}

You can then use this logger to "pass down" to all methods where needed:

Layer1(new IndentedLogger(@"C:\test.txt", "----"));

public void Layer1(IndentedLogger log)
{
    log.WriteIndentedMessage("Layer1");
    log.WriteMessage("Message1");
    Layer2(log.Next());
}

public void Layer2(IndentedLogger log)
{
    log.WriteIndentedMessage("Layer2");
    log.WriteMessage("Message2");
    Layer3(log.Next());
}

public void Layer3(IndentedLogger log)
{
    log.WriteIndentedMessage("Layer3");
    log.WriteMessage("Message3");
}

Which will give you the following output:

----Layer1
Message1
--------Layer2
Message2
------------Layer3
Message3

However, were Layer3 to be called directly by Layer1, you would get:

----Layer1
Message1
--------Layer3
Message3

Which means that your indentation changes based on how deep into the nested logic you are.

At this point, you can use whatever style you want. But the necessity of having a custom class tailored to do what you want should be clear.


Doing it another way

The one big problem I have with your approach is that you end up choosing what is important to you. However, some log files contain a varied type of information. Sometimes (e.g when hunting a bug) you want to see lines A,B,C, but other times (e.g. when tracking performance) you want to see lines A,C,E.

What you're doing now is deciding a single way of how you want to view the data.

A better approach would be to post-process the log file based on what you want. For example, you can add an identifier to each log line; which you can later use to find relevant lines. If you're using excel, you can apply color coding to the log based on the type found in the line.

Identifiers could be just about any arbitrarily chosen string. "CREATE_USER", "ERROR", "PERFORMANCE", ... or you could use the more standard log levels: Fatal/Error/Warning/Info/Debug/Trace. I can't answer this for you, pick whichever identifier seems best and unambiguous.

This makes it possible for you to highlight the log messages of type A,B,C and for your colleague to highlight the log messages of type A,C,E. You simply have to use different Excel formatting rules, but the log remains the same.

0

If you are running a single thread and things are just expected to be sequential, this works fine. If you are considering multiple concurrent sequences, then why not prefix with a session or thread identifier and an operation,e.g

pid<1234>/tid<55>/MyProgram/OperationABC: I am doing something here 

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.