Correct logging in the Microsoft .NET Framework

Why do we need logs

Obviously, logs are made for developers to make their lives easier for them (us). The main purposes for which there are logs:

say what the system is doing right now, without using the debugger, because it is sometimes not justified;
to “investigate” the circumstances that led to a certain state of the system (for example, a fall or bug);
analyze what is spent more time / resources, i.e. profiling.

Primitive approach

It would seem that everything is simple:

public static void Log( string message) { File .AppendAllText( "log.txt" , message); }

Why invent something else, connect external libraries, set up configs?
In practice, it turns out that everything is wrong: one log file is no longer enough, problems arise with multithreading, log format, time recording, performance, etc.
What features should a good logger support?

Features of a good logger

Logging Levels and Message Filtering
Typical levels: Debug, Info, Warn, Error, Fatal
The levels help to determine the criticality of the message and the acceptable response time to it, more on this later.
Log files rotation
Logs grow over time, old ones become unnecessary. A good logger should be able to replace the active file when certain conditions occur. There are two modes: by date and by file size.
The ability to record messages not only in files
Not always a file is the best way to store messages, a good logger should support sending messages via UDP protocol, writing to the database, interaction with message queues, such as MSMQ or JMS. In addition, it’s great when the logger provides the ability to implement its own message consumer (usually referred to as the term message consumer, or message appender).
Thread-safety
Thread safety is a very important requirement for a logger. A bad logger can:

skip some messages;
throw an exception
adversely affect performance

Competent implementation of thread safety in the logger is one of the key points.
Asynchronous logging
Typical logging practice is asynchronous writing. It is important that the buffer size is flexibly customizable, for example, debug messages can be written 100 pieces each, and error - immediately after the occurrence.
Log format and configuration
The format should be customizable, with the ability to specify what to write and where to write. For example, you can write to a file stored on the path from an environment variable. In addition, a useful feature is the dynamic configuration of the logger, tracking the configuration file. You need to enable debug mode - changed the config and enjoy the delicious logs without restarting the application.

What and how to write logs

We considered features of logger. But to get a good, readable log, you need to keep logs correctly.
Let's start with the fact that usually the “law” of any service or department is an SLA, a service level agreement. It specifies the permissible levels of recovery after a failure, the time of an acceptable reaction to messages, etc. Logging levels are available to help meet the SLA and respond to an event in time.
')

Logging levels

It is very important to understand that any message carries information of a certain criticality, and the reaction time to messages is different. I will give an example:

Debug.
Debug.
Debug. 0.02 , 1000
Info. 40000000000 (John Doe), $2000.
Warn. 0.
Error. 123: …..
Fatal. MSMQ, - (…). .

What does each level mean?

Debug : debug messages, profiling. In a production system, messages of this level are usually included when the system is initially started or to search for bottlenecks (bottlenecks).
Info : ordinary messages informing about system actions. There is no need to react to such messages at all, but they can help, for example, when searching for bugs, investigating interesting situations, and so on.
Warn : recording such a message, the system tries to attract the attention of service personnel. Something strange happened. Perhaps this is a new type of situation, not yet known to the system. It is necessary to understand what happened, what it means, and relate the situation to either the info message or an error. Accordingly, it is necessary to modify the processing code for such situations.
Error : system error requiring intervention. Something did not survive, something fell off. Need to take action pretty quickly! Errors of this level and higher require immediate logging in order to speed up the reaction to them. It should be understood that a user error is not a system error. If the user entered in the field -1, where it was not intended - do not write about it in the error log.
Fatal : This is a special class of errors. Such errors lead to the inoperability of the system as a whole, or the inoperability of one of the subsystems. Most often fatal errors occur due to incorrect configuration or equipment failures. They require an immediate, immediate response. Perhaps you should provide notification of such errors by SMS.

Correct determination of error levels affects the quality of the system and the simplicity of its maintenance.

Life example of choosing levels

Let's imagine that the system being developed is a postal employee who accepts parcels. Brought the parcel.

Debug: 1. …
Debug: 1: 40x100
Debug: …
Debug: 1: 1
Debug: …
Info ( Error!): 1 40x100, 1, :
…
Info: 2 20x60, 0.5 1
…
Warn: 3: : 2050-01-01
…
Error: : :
…
Fatal: . .

Logs and exceptions

They are inseparable, like Lenin and the party. Exception or error handling often needs to be properly logged.
Bad example:

Log(ex.ToString());

Even worse:

Log(ex.Message);

Do not write exceptions without accompanying text in the logs. Having seen the stack trace that doesn’t say anything, I personally come into a panic. What is it - a mistake, a notification? How did the program respond to this exception? Continued to work in normal mode, fell, waiting for the response of the administrator? Unfortunately, I often see it in the code, which is very sad. The right way:

Log( " {0} , : {1}" , account, ex);

Rules for writing exceptions to logs

select the level (subsystem) where you will log exceptions;
If you have processed an exception, three cases are possible:
- An exception is considered processed and is not passed up the stack. In this case, write an exception with a detailed stack to the log;
- An exception is thrown up the stack in the same subsystem. Do not log such an exception. However, make sure that it is higher up the stack;
- an exception is thrown up the stack to another subsystem. For example, on another machine or in a different process. Pledge such an exception, or record a diagnostic exception message;
if the exception is not processed, do not log it. However, make sure that the above exception will be logged. I will explain:
try { … } catch (Exception ex) { Log(ex); throw ; }

A catch branch in which a single call to the logger is the wrong option. Get rid of such a catch.

These simple rules help not to turn logs into a dump from trace stack when an error occurs.
Yes, do not forget that ex.ToString () - will output an exception with the text and stark trace. Sometimes for some reason they forget about this useful method.

Logger comparison

Let's compare what we are offered by NLog, Log4net, Enterprise Library.

	Nlog	Log4net	Enterprise Library
License	BSD	Apache	MS-PL
Levels	Debug Trace Info Warn Error Fatal	Debug Info Warn Error Fatal	Verbose Information Warning Error Critical
Log rotation	Yes	Yes	Yes
Config tracking	Yes	Yes	Not (?)
Array logging	Not	Yes	Not
Thread safety	Yes	Yes	Yes
Protocols	Network Memory Msmq Base ... extensions	WMI Network Memory Base ... extensions	WMI Msmq Base ... extensions
Buffering, asynchronous logging	Yes	Yes	Yes
condition	Active	Probably abandoned. The last bug in bugtrack (http://issues.apache.org/jira/) was fixed in March 2009	Active

Earlier I used log4net, now I switched to NLog, because log4net abandoned (sorry).

findings

Do not write the logger yourself;
learn the configs and capabilities of the logger you are using;
correctly select the level of messages in the log;
watch out for logging exceptions.