How to write logs (?)

The topic may be trivial, but when the program starts to work somehow wrong, and in general it behaves very strangely, you often have to read the logs. And there are a lot of logs, especially if there is no way to debug the program and you cannot reproduce the error. Probably everyone worked out some rules for themselves, what, how and when to log. Below I want to consider a few rules for writing messages to the log, and there will also be a small comparison of the logging libraries for php, ruby ​​and go. Log collectors and delivery systems will not be considered consciously (they have been discussed many times already).

There is such a linux utility, as well as a part-time network protocol called syslog. And there is a whole set of RFC dedicated to syslog, one of them describes the logging levels https://en.wikipedia.org/wiki/Syslog#Severity_level (https://tools.ietf.org/html/rfc5424 ). According to rfc 5424, 8 logging levels are defined for syslog, for which a brief description is also given. These logging levels have been adopted by many popular loggers for different programming languages. For example, http://www.php-fig.org/psr/psr-3/defines the same 8 levels of logging, and the standard Ruby logger uses a slightly reduced set of 5 levels. Despite the formal indication in which cases one or another level of logs should be used, a combination like debug / info / fatal is often used - the first for logging during development and testing, the second and third in terms of production. Then at some point on the production something incomprehensible begins to happen and suddenly it turns out that the info logs are not enough - we run enable debug. And if they do not heavily load the system, then they often remain included in the production environment. In fact, there are two scenarios when you need to have logs:

• something is happening and you need to know what
• something is broken and you need to activate the trigger

According to the trigger, the following may occur: notification of an error by email, abnormal termination or restart of the program, or other typical scenarios.

In the Go language, in which everything is simplified to the limit, the standard logger also decently shredded and left the following options:

• Fatal - output to the log and immediate exit to the OS.
• Panic - logging and “panic” stimulation (analog of exception)
• Print - just prints a message to the log

Confused that use in a specific situation is almost impossible. But messages in such a strongly truncated form are difficult to analyze, as well as to set up warning systems that typically respond to some kind of Alert \ Fatal \ Error in the log text.

When writing a program from scratch, I often use the debug level for logging everywhere, with the expectation that the production will have the info logging level set and thereby reduce the noise level in messages. But in this approach, a situation often arises that the logs suddenly become missed. It is difficult to guess what information is needed to catch a rare bug. It is possible to always rationally use the info level by default, and error handlers have an error level or higher. But if you have hundreds or more log messages per second, then it probably makes sense to fine-tune between info / debug. In such situations, it already makes sense to use specialized solutions so as not to waste performance.

There is another subtle point when you write something likelogger.debug(entity.values)- then with the logging level set higher than debug, the contents of entity.values ​​will not get into the log, but it will be calculated each time by consuming resources. In Ruby logger can be transmitted instead of lines of code block messages: Logger.debug { entity.values }. In this case, calculations will only occur when the appropriate log level is set. In Go, to implement lazy computing, an object supporting the Stringer interface can be passed to the logger.

After you have figured out using the log levels, you still need to be able to connect disparate messages, this is especially true for multi-threaded applications or related separate services, when all messages are mixed up in the logs.

The typical format of the message line in the log can be divided into the following components:

[system info] + [message] + [context]

Where:

• system info: timestamp, process id, thread id and other overhead information
• message: Message text
• context: any additional information, context may be common for messages within the framework of some operation.

In order to connect request / response pairs, an http header is often used X-Request-ID. Such a header can be generated by the client, or it can be generated on the server side. Adding it to the context of each line of the log, it will be possible with a flick of the wrist to find all messages that have arisen as part of a specific request. And in the case of distributed systems, the header can be transmitted further along the chain of network calls.

But with a single context within the request, a problem arises with various ORM, http clients or other services / libraries that live their own lives. And it’s even better if they provide the ability to redefine their standard logger at least globally, but setting the context for the logger as part of the request is often not realistic. This problem is mainly relevant for multi-threaded processing, when one process serves many requests. But for example, the Rails framework has very tight integration between all components and ActiveRecord requests can be logged along with the global context for the current network request. And in the Go language, some logging libraries allow you to dynamically create a new logger object with the desired context, it looks something like this:

reqLog := log.WithField("requestID", requestID)

After that, such an instance of the logger can be passed as a dependency to other objects. But the lack of a standardized logging interface (for example, as psr-3 in php) provokes the creators of hardcode libraries to incompatible implementations of loggers. Therefore, if you write your library on Go and it has a logging component, do not forget to provide an interface for replacing the logger with a user one.

In summary:

• Log in excess. It is never known beforehand how much and what information in the logs will be needed at a critical moment.
• Eight levels of logging - do you really need so much? From experience, a maximum of 3-4 should be enough, and then provided that event handlers are configured for them.
• If possible, use lazy calculations to log messages
• Always add the current context to each log message, at least requestID.
• If possible, configure third-party libraries so that they use a logger with the current request context.