There is no debate that structured logging has many advantages over the alternative, and Go 1.21 finally introduced a wonderful new package slog that brought structured logging into the standard library. In addition, it also supports different log levels, such as slog.Info, slog.Debug, slog.Warn, and slog.Error.
In this post, I will present an experimental package serrors for providing structured error support, and we’ll see how it naturally correlates with structured logging.
What Is Structured Logging
First, let’s recall what structured logging is. The Go `slog` Blog describes it as:
Structured logs use key-value pairs so they can be parsed, filtered, searched, and analyzed quickly and reliably. For servers, logging is an important way for developers to observe the detailed behavior of the system, and often the first place they go to debug it. Logs therefore tend to be voluminous, and the ability to search and filter them quickly is essential.
This short summary mentions a couple of things:
- What is structured logging?
They are just key-value pairs, instead of one string message. - Why is it good for?
key-value pairs are more convenient to be consumed by machines, making it easier to process, parse, filter, and so on.
Example:
In package log we have the Printf function:
package log
func Printf(format string, v ...any)When logging with log.Printf your output will look like this:
log.Printf("user %d created an article %s", userID, articleID)
// output
// 2009/11/10 23:00:00 user 123 created an article abcPackage slog supports log levels and introduces functions that take the message and key pairs (args):
package slog
func Info(msg string, args ...any) {...}
func Debug(msg string, args ...any) {...}
func Warn(msg string, args ...any) {...}
func Error(msg string, args ...any) {...} Note the variadic argument
args— These are the key pairs, also called attributes. There is a very interesting discussion on theanypart, instead of receiving a type likelogrusreceives. I won’t get into it but rest assured that if you rungo veton an odd number of attributes, it will fail. Personally, I really like this style as I’m already used to it from the packagego-kit/log, and I think it has many advantages over the others. There is an interesting discussion here about variadic argument in general.
Anyway, instead of formatting the attributes inside our message, as we did using log.Printf, we now can actually send these as attributes:
slog.Info("user created an article",
"userID", userID,
"articleID", articleID,
)
// output
// 2009/11/10 23:00:00 INFO user created an article userID=123 articleID=abcIn addition, slog supports custom handlers. One of the built-in handlers slog provides us is JSON which outputs the log as JSON:
logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
logger.Info("user created an article",
"userID", userID,
"articleID", articleID,
)
// output
// {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"user created an article","userID":123,"articleID":"abc"}Errors are (sometimes) Logs
So how does all of this relate to structured errors, and what does it even mean?
Well, I’m happy you’ve asked. When you encounter an error, you must handle it, either to return the error to the caller or log it. Not both.
func doSomething() error {
// some code
if err := doSomethingElse(); err != nil {
// log the error
}
// more code
return nil
}This is an example where you will log the error, but the caller of doSomething won’t know about the error.
Usually, somewhere in that chain, you would like to log that something went wrong, usually at the first caller.
Wrapping Errors
Go 1.13 added support for wrapping and unwrapping errors as part of the standard library. This was a much-needed addition that enabled you to trace back the error chain and check for error types and behavior through it.
When you log an error, the err.Error() will give you an error message composed of all the messages through the chain. What if some errors have specific data and attributes that you would like to know for debugging purposes? You will need to add these to their messages probably.
This is where structured errors comes into play. A structured error is just an error that has attributes. When logging an error, it will automatically add these attributes to the log record.
Package `serrors`
First, let’s look at the package interface. We will have a New and Wrap functions that will receive key-value argument, such as slog functions receive:
func New(err error, args ...any)
func Wrap(err error, msg string, args ...any)Example use-case:
func doSomething(userID int, articleID string) error {
// some work
if err := doRiskyThing(); err != nil {
return serrors.Wrap(err, "doSomething",
"userID", userID,
"articleID", articleID,
)
}
// more work
return nil
}
func doRiskyThing() error {
return fmt.Error("doRiskyThing always fail")
}As you can see, here I use the function serros.Wrap. The functiondoSomething returns an error that has the attributes attached.
In order for the function log.Error to automatically take these attributes, we will add an error argument to the function slog.Error:
func Error(msg string, err error, args ...any)Well, obviously this is something that can’t be done, it’s only for this example. In the example repo with the experimental implementation, I’ve added a function
LogErrorinto theserrorspackage.
To log the error you will simply use:
logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
if err := doSomething(userID, articleID); err != nil {
logger.Error("failed something", err)
}
// output
// {"time":"2009-11-10T23:00:00Z","level":"ERROR","msg":"failed something: doSomething: doRiskyThing always fail","userID":123,"articleID":"abc"}The output message is err.Error() concatenated to msg , and you can see all the attributes that were added through the serror.Wrap function call. These attributes will include all the attributes in the error chain.
A sample GitHub repo with some source code for the experimental implementation of serrors can be found here.
Conclusion
The integration of structured logging in Go 1.21 marks a significant natural advancement. By adding the concept of structured errors and adopting key-value pairs for both logging and error handling, developers could create highly informative, easily parsed, and efficiently analyzed logs and errors. This synergy between structured logging and structured errors enables us a quicker issue identification and resolution. Hopefully :-p
