Let's talk about logging
- Transfer
This post is inspired by a topic in the Go Forum , launched by Nate Finch. This post is focused on the Go language, but if you go past this, I think the ideas presented here are widely applicable.
The log package in Go does not have log levels, you can manually add the prefixes DEBUG, INFO, WARN, and ERROR yourself. Also, the logger type in Go does not have the ability to enable or disable these levels separately for selected packages. For comparison, let's look at a few of its replacements from third-party developers. Google's
glog has levels:
Let's look at another library, loggo , designed for Juju, levels are available:
Loggo also has the ability to set the level of log detail for the desired packages individually.
Here are two examples, explicitly created under the influence of other libraries for logging in other languages.
In fact, their origin can be traced back to syslog (3), perhaps even earlier. And I think they are wrong.
I want to take a controversial position. I think all library libraries are bad because they offer too many features; a stunning set of features that stuns a programmer right at the moment when he has to clearly think about how to communicate with the reader from the future, with those who will view these magazines.
I argue that successful log packages require far fewer features and, of course, fewer levels.
Let's start with the simplest. Nobody needs the WARNING log level.
Nobody reads the warnings, because by definition nothing bad happened. Perhaps something may go wrong in the future, but it sounds like someone else, and not my problem.
In addition, if you use some kind of multi-level logging, why should you set the level of WARNING? You would set the INFO or ERROR level. Setting the WARNING level means that you are likely to log errors at the WARNING level.
Exclude the warning level — this is either an informational message or an error.
The FATAL level actually logs the message, and then calls os.Exit (1). In principle, this means:
In fact, log.Fatal is less verbose, but semantically equivalent to panic.
It is generally accepted that libraries should not use panic1, but if calling log.Fatal2 has the same effect, it should also be prohibited.
Assumptions that this cleanup problem can be solved by registering shutdown handlers in the logger provides a close connection between the logger used and every place where cleanup operations occur. It also violates the division of interests.
Do not write messages with the FATAL level, prefer to return the error to the caller instead. If the error reaches main.main, then this is the right place to perform any cleanup actions before terminating the program.
Error handling and logging are closely related, therefore, at first glance, error level registration (ERROR) should be easily justified. I disagree.
In Go, if a call to a function or method returns an error value, then you really have two options:
If you decide to process the error by writing it to the log, then by definition it is no longer an error - you have processed it. The very act of registering an error is an error handling, therefore, it is no longer advisable to record it in the log as an error.
Let me convince you with this code snippet:
You should never register anything at the error level, because you must either handle the error or pass it on to the caller.
It should be clearly understood, I am not saying that you should not write to the log that a change of state has occurred:
But in reality, log.Info and log.Error have the same goal.
I do not say "do not register errors"! Instead, I put the question, what is the smallest possible API for logging (logging)? And when it comes to errors, I believe that the overwhelming majority of things recorded at the ERROR level are simply done this way, because they are associated with an error. In fact, they are just informational, so we can remove error-level logging (ERROR) from our API.
We excluded warnings (WARNING), argued that nothing should be recorded at the error level (ERROR), and showed that only the top level of the application should have a kind of log.Fatal behavior. What is left?
I believe that there are only two things that you need to log:
Obviously, these are debugging (DEBUG) and informational (INFO) levels, respectively.
log.Info should simply write this line to the log output. It should not be possible to turn it off, as the user should only tell what is useful to him. If an error occurs that cannot be processed, it should appear in main.main where the program ends. Minor inconvenience associated with the need to insert the FATAL prefix before the final log message or recording directly into os.Stderr using fmt.Fprintf is not a sufficient reason to extend the package with the log.Fatal mod.
log.Debug, this is a completely different matter. It is needed by the developer or support engineer to monitor the operation of the program. During development, the debug expressions (debugs) should be numerous, without resorting to the trace level (trace) or debug2 (you know who you are). A logging package must support detailed control to enable or disable debug expressions, for the packets that are needed, or perhaps even in a narrower scope.
If it were a Twitter poll, I would ask you to choose between
But the fact is that logging is both. The solution to this problem MUST be to destroy and mercilessly reduce unnecessary distractions.
What do you think? Is it crazy enough to work, or just crazy?
Some libraries may use panic / recover as an internal control flow mechanism, but the basic mantra is that they should not allow leakage of these operations of the control flow beyond the package boundary.
Ironically, although there is no DEBUG output level, the standard Go logging package has Fatal and Panic functions. In this package, the number of functions that lead to a sudden program termination exceeds the number of those that do not.
The author of this article, Dave Cheney , is the author of many popular Go packages, for example github.com/pkg/errors and github.com/davecheney/httpstat . You can evaluate the authority and experience of the author yourself.
Regarding logging, quite a lot of developers are concerned, some have discussed adding the Logger interface to the standard Go library in order to streamline logging in libraries and so encourage their developers. The guys even made their proposal and put the document up for discussion.
Plus presentation thinking Do we need a new logger and how should it be? by Chris Hines.
There are several implementations of Dave’s go-log ideas and a bit more elaborate ERROR level and more elaborate logr package .
Why is there no love?
The log package in Go does not have log levels, you can manually add the prefixes DEBUG, INFO, WARN, and ERROR yourself. Also, the logger type in Go does not have the ability to enable or disable these levels separately for selected packages. For comparison, let's look at a few of its replacements from third-party developers. Google's
glog has levels:
- Info
- Warning
- Error
- Fatal (ends the program)
Let's look at another library, loggo , designed for Juju, levels are available:
- Trace
- Debug
- Info
- Warning
- Error
- Critical
Loggo also has the ability to set the level of log detail for the desired packages individually.
Here are two examples, explicitly created under the influence of other libraries for logging in other languages.
In fact, their origin can be traced back to syslog (3), perhaps even earlier. And I think they are wrong.
I want to take a controversial position. I think all library libraries are bad because they offer too many features; a stunning set of features that stuns a programmer right at the moment when he has to clearly think about how to communicate with the reader from the future, with those who will view these magazines.
I argue that successful log packages require far fewer features and, of course, fewer levels.
Let's talk about warnings (WARNING)
Let's start with the simplest. Nobody needs the WARNING log level.
Nobody reads the warnings, because by definition nothing bad happened. Perhaps something may go wrong in the future, but it sounds like someone else, and not my problem.
In addition, if you use some kind of multi-level logging, why should you set the level of WARNING? You would set the INFO or ERROR level. Setting the WARNING level means that you are likely to log errors at the WARNING level.
Exclude the warning level — this is either an informational message or an error.
Let's talk about the level of unrecoverable error (fatal)
The FATAL level actually logs the message, and then calls os.Exit (1). In principle, this means:
- отложенные выражения в других подпрограммах(горутинах) не выполняются;
- буферы не очищаются;
- временные файлы и каталоги не удаляются.
In fact, log.Fatal is less verbose, but semantically equivalent to panic.
It is generally accepted that libraries should not use panic1, but if calling log.Fatal2 has the same effect, it should also be prohibited.
Assumptions that this cleanup problem can be solved by registering shutdown handlers in the logger provides a close connection between the logger used and every place where cleanup operations occur. It also violates the division of interests.
Do not write messages with the FATAL level, prefer to return the error to the caller instead. If the error reaches main.main, then this is the right place to perform any cleanup actions before terminating the program.
Let's talk about the error (ERROR level)
Error handling and logging are closely related, therefore, at first glance, error level registration (ERROR) should be easily justified. I disagree.
In Go, if a call to a function or method returns an error value, then you really have two options:
- handle the error.
- return error to your caller. You can beautifully wrap a mistake in a gift wrap, but this is not important for this discussion.
If you decide to process the error by writing it to the log, then by definition it is no longer an error - you have processed it. The very act of registering an error is an error handling, therefore, it is no longer advisable to record it in the log as an error.
Let me convince you with this code snippet:
err := somethingHard()
if err != nil {
log.Error("oops, something was too hard", err)
return err // what is this, Java ?
}You should never register anything at the error level, because you must either handle the error or pass it on to the caller.
It should be clearly understood, I am not saying that you should not write to the log that a change of state has occurred:
if err := planA(); err != nil {
log.Infof("could't open the foo file, continuing with plan b: %v", err)
planB()
}
But in reality, log.Info and log.Error have the same goal.
I do not say "do not register errors"! Instead, I put the question, what is the smallest possible API for logging (logging)? And when it comes to errors, I believe that the overwhelming majority of things recorded at the ERROR level are simply done this way, because they are associated with an error. In fact, they are just informational, so we can remove error-level logging (ERROR) from our API.
What is left?
We excluded warnings (WARNING), argued that nothing should be recorded at the error level (ERROR), and showed that only the top level of the application should have a kind of log.Fatal behavior. What is left?
I believe that there are only two things that you need to log:
- things that developers care about when they develop or debug a program;
- things that excite users when using your program.
Obviously, these are debugging (DEBUG) and informational (INFO) levels, respectively.
log.Info should simply write this line to the log output. It should not be possible to turn it off, as the user should only tell what is useful to him. If an error occurs that cannot be processed, it should appear in main.main where the program ends. Minor inconvenience associated with the need to insert the FATAL prefix before the final log message or recording directly into os.Stderr using fmt.Fprintf is not a sufficient reason to extend the package with the log.Fatal mod.
log.Debug, this is a completely different matter. It is needed by the developer or support engineer to monitor the operation of the program. During development, the debug expressions (debugs) should be numerous, without resorting to the trace level (trace) or debug2 (you know who you are). A logging package must support detailed control to enable or disable debug expressions, for the packets that are needed, or perhaps even in a narrower scope.
Conclusion
If it were a Twitter poll, I would ask you to choose between
- logging is important
- logging is hard
But the fact is that logging is both. The solution to this problem MUST be to destroy and mercilessly reduce unnecessary distractions.
What do you think? Is it crazy enough to work, or just crazy?
Notes
Some libraries may use panic / recover as an internal control flow mechanism, but the basic mantra is that they should not allow leakage of these operations of the control flow beyond the package boundary.
Ironically, although there is no DEBUG output level, the standard Go logging package has Fatal and Panic functions. In this package, the number of functions that lead to a sudden program termination exceeds the number of those that do not.
about the author
The author of this article, Dave Cheney , is the author of many popular Go packages, for example github.com/pkg/errors and github.com/davecheney/httpstat . You can evaluate the authority and experience of the author yourself.
From translator
Regarding logging, quite a lot of developers are concerned, some have discussed adding the Logger interface to the standard Go library in order to streamline logging in libraries and so encourage their developers. The guys even made their proposal and put the document up for discussion.
Plus presentation thinking Do we need a new logger and how should it be? by Chris Hines.
There are several implementations of Dave’s go-log ideas and a bit more elaborate ERROR level and more elaborate logr package .