How to write logs (?)
The theme may be trivial, but when the program starts to work as something wrong, and generally behave very strange, you often have to read the logs. And a lot of logs, especially if there is no possibility to debug the program and fail to reproduce the error. Probably everyone has developed some rules for himself, what, how and when to log. Below I want to consider several rules for writing messages to the log, and there will also be a small comparison of logging libraries for php, ruby and go. Log collectors and delivery systems will not be deliberately considered (they have been discussed many times already).
There is such a linux utility, as well as a 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 levels of logging are defined for syslog, for which a brief description is also given. These logging levels were adopted by many popular loggers for various 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 of when this or that level of logs should be used, a combination like debug / info / fatal is often used - the first one is used for logging during development and testing, the second and the third are taken into account for production. Then, at some point in the production, something incomprehensible starts to happen and suddenly it turns out that info logs are not enough - we are running to enable debug. And if they do not heavily load the system, they often remain included in the production environment. In fact, there are two scenarios when you need to have logs:
The trigger can occur: error notification by email, crash or restart of the program or other typical scenarios.
In the Go language in which everything is simplified to the limit, the standard logger is also decently cut off and left the following options:
')
It is almost impossible to get confused about what to use in a specific situation. 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 text of the log.
When I write a program from scratch, I often use the debug level for logging with the expectation that the level of info logging will be set on the production and thus the noisiness of messages will be reduced. But in this approach, there is often a situation that logs suddenly become missed. It is difficult to guess what information is needed to catch a rare bug. It is possible to always use the default info level by default, and error handlers in error handlers and above. But if you have hundreds and more log messages per second, then you probably have a sense of fine-tuning between info / debug. In such situations, it already makes sense to use specialized solutions so as not to squander performance.
There is also a subtle moment when you write something like
After you have figured out using log levels, you need to be able to bind disparate messages, this is especially true for multi-threaded applications or related services, when all messages are mixed up in logs.
The typical format of a message line in a log can be divided into the following components:
Where:
In order to associate request / response pairs, the http header
But with a single context within the request, there is a problem with various ORM, http clients or other services / libraries that live their own lives. And it’s still good if they provide an opportunity to redefine your standard logger at least globally, but setting the context for the logger within the query is often not realistic. This problem is mainly relevant for multi-threaded processing, when one process serves multiple requests. But for example, in the Rails framework, there is a very tight integration between all components and ActiveRecord requests can be written to the log 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 like this:
After that, such an instance of the logger can be transferred as a dependency to other objects. But the absence of a standardized logging interface (for example, as psr-3 in php) provokes the creators of hardcod libraries of low-compatible 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 custom one.
Summarizing:
There is such a linux utility, as well as a 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 levels of logging are defined for syslog, for which a brief description is also given. These logging levels were adopted by many popular loggers for various 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 of when this or that level of logs should be used, a combination like debug / info / fatal is often used - the first one is used for logging during development and testing, the second and the third are taken into account for production. Then, at some point in the production, something incomprehensible starts to happen and suddenly it turns out that info logs are not enough - we are running to enable debug. And if they do not heavily load the system, they often remain included in the production environment. In fact, there are two scenarios when you need to have logs:
- something happens and you need to know what
- something broke and you need to additionally activate the trigger
The trigger can occur: error notification by email, crash or restart of the program or other typical scenarios.
In the Go language in which everything is simplified to the limit, the standard logger is also decently cut off and left the following options:
')
- Fatal - output to the log and immediate output to the OS.
- Panic - output to the log and the excitement of "panic" (analogue exceptions)
- Print - just displays a message in the log
It is almost impossible to get confused about what to use in a specific situation. 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 text of the log.
When I write a program from scratch, I often use the debug level for logging with the expectation that the level of info logging will be set on the production and thus the noisiness of messages will be reduced. But in this approach, there is often a situation that logs suddenly become missed. It is difficult to guess what information is needed to catch a rare bug. It is possible to always use the default info level by default, and error handlers in error handlers and above. But if you have hundreds and more log messages per second, then you probably have a sense of fine-tuning between info / debug. In such situations, it already makes sense to use specialized solutions so as not to squander performance.
There is also a subtle moment when you write something like
logger.debug(entity.values) - then, if the logging level is set higher, the debug content of entity.values will not be included in the log, but it will be calculated every time after eating the resources. In Ruby, you can pass a block of code instead of a message line to a Logger.debug { entity.values } : Logger.debug { entity.values } . In this case, the calculations will occur only when the appropriate log level is set. In the Go language, to implement lazy evaluation, an object supporting the Stringer interface can be passed to the logger.After you have figured out using log levels, you need to be able to bind disparate messages, this is especially true for multi-threaded applications or related services, when all messages are mixed up in logs.
The typical format of a message line in a log can be divided into the following components:
[system info] + [message] + [context] Where:
system info: time stamp, process id, thread id and other service informationmessage:messagetextcontext: any additional information, the context may be common to the messages within an operation.
In order to associate request / response pairs, the http header
X-Request-ID often used. 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 will allow you to easily find all messages arising from the execution of a specific query with a slight movement of your hand. And in the case of distributed systems, the header can be passed on through the network call chain.But with a single context within the request, there is a problem with various ORM, http clients or other services / libraries that live their own lives. And it’s still good if they provide an opportunity to redefine your standard logger at least globally, but setting the context for the logger within the query is often not realistic. This problem is mainly relevant for multi-threaded processing, when one process serves multiple requests. But for example, in the Rails framework, there is a very tight integration between all components and ActiveRecord requests can be written to the log 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 like this:
reqLog := log.WithField("requestID", requestID) After that, such an instance of the logger can be transferred as a dependency to other objects. But the absence of a standardized logging interface (for example, as psr-3 in php) provokes the creators of hardcod libraries of low-compatible 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 custom one.
Summarizing:
- Log in abundance. You never know in advance 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? By experience, a maximum of 3-4 should suffice, and then provided that event handlers are configured for them.
- If possible, use lazy calculations to display messages in the log
- Always add the current context to each log message, at least the requestID.
- If possible, customize third-party libraries so that they use the logger with the current request context.
Source: https://habr.com/ru/post/327834/
All Articles