Structured Logging In Go Using Standard Library - Slog

Learn how to use log/slog from Go 1.21

by Percy Bolmér, June 9, 2023

Structured logging is a really important thing in applications, which is why I am so happy to see that we can finally use the Std lib in Go to perform it. 

About a year ago I wrote an article about how to perform structured logging in Go, In that article I recommend third-party libraries such as Lumberjack, Zerolog, Logrus, and Zap.

Since the release of Go 1.21, there is no longer any need to rely on those libraries.

And fewer third-party dependencies is an amazing thing that I always strive for.

Whats harm is using a third party logging library gonna do to you? Well, ask the users of Log4J.

As systems grow larger, logs and metrics play an increasingly important role in understanding what is happening inside the systems.

A structured log is simple what it sounds like, instead of printing a single line of random text, we print out structured logging information, commonly found in such structure as the date, service, and severity or level. It does not have to be JSON, It can also be a structured text row.

An example can be the

{ "date": "2024-06-21", "service": "buggy-script", "level": "warning", "message": "something went wrong", "context": "myFuncThatfails"}

The advantages are many, easily readable, but most importantly we can ingest the logs into monitoring systems to get a better understanding and overview of the applications.

How To Use Structured Logs With Slog

To get started make sure you have Go installed, and the version has to be above 1.21. You can download the latest go here.

Create a new directory and initialize a Go module.

mkdir slogtest
cd slogtest
go mod init programmingpercy/slogtest

To use Slog, we can simply import the log/slog module and get started. Much like the log module, there is a default logger that we can use right of the bat if we don’t want to customize it.

package main

import (
 "log/slog"
)

func main(){
 slog.Info("test")
}

Running that software using go run main.go will trigger the following output

2023/08/09 19:03:43 INFO test

Log Levels And Level Functions

An important part of any structured logging solution is log levels. 

The common approach is to have a few severity levels, and depending on your configuration you only see logs more severe than the configuration. 

Log levels are always hierarchical, what this means is that if we have set the applications log level to Debug, we would see all logs, no matter the level.

If we instead up increase the log level into Info, we would no longer see Debug logs, since debug is lower in the hierarchy.

In Slog, we have the following levels, each level is a higher severity than the previous. (PS. How you use the levels is up to you, its important to understand that they do have a hierarchical ranking)

• Debug - Any information needed when debugging
• Info - Basic information about what the application is up to
• Warn - A warning in the application
• Error - Something went wrong

Each level comes as a function in the slog module. If you use slog.Info it will print an Info log etc.

All these level functions follows the same function signature. Which means we use them in the same way, regardless of the level.

func(msg string, args ...any)

The level functions (Debug, Info, Warn, Error) all accept the message as the first parameter.

Let’s print a message for each level and see what happens.

package main

import (
 "log/slog"
)

func main(){
 slog.Debug("debug level")
 slog.Info("info level")
 slog.Warn("warn level")
 slog.Error("error level")
}

Now run the software with go run main.go and you should see the following.

2023/08/09 19:37:45 INFO info level
2023/08/09 19:37:45 WARN warn level
2023/08/09 19:37:45 ERROR error level

Now, you might be wondering where the Debug level is?

The default log Handler that we are using when calling on the Log functions directly from the slog module won’t print Debug logs.

This is because it is configured with the log level of info.

To see the debug logs, we need to create a new Handler which is used to print out logs, and then set the Log level appropriately.

There are two Handlers right now, JSON and Text. The default that we have seen is an internal Slog handler named defaultHandler.

We will start off with the Text handler, and then try out a JSON handler to see the difference.

We can create the Handlers using either NewTextHandler or NewJSONHandler. Again, the function signatures are the same.

func(w io.Writer, opts *slog.HandlerOptions) *slog.TextHandler

The return type is different, but we can easily swap between the two thanks to this.

The handlers want an io.writer, and we want to print to stdout so I will simply print to os.Stdout so the logs appear in my terminal. The second argument is a slog.HandlerOptions, this is the place where we change how the logger behaves, such as log level.

The HandlerOptions is a struct with 3 fields, It allows us to set the log level, add the source code that triggers the log, or replace attributes if you want different timestamp format etc.

// HandlerOptions are options for a TextHandler or JSONHandler.
// A zero HandlerOptions consists entirely of default values.
type HandlerOptions struct {
 // AddSource causes the handler to compute the source code position
 // of the log statement and add a SourceKey attribute to the output.
 AddSource bool

 // Level reports the minimum record level that will be logged.
 // The handler discards records with lower levels.
 // If Level is nil, the handler assumes LevelInfo.
 // The handler calls Level.Level for each record processed;
 // to adjust the minimum level dynamically, use a LevelVar.
 Level Leveler

 // ReplaceAttr is called to rewrite each non-group attribute before it is logged.
 // The attribute's value has been resolved (see [Value.Resolve]).
 // If ReplaceAttr returns a zero Attr, the attribute is discarded.
 //
 // The built-in attributes with keys "time", "level", "source", and "msg"
 // are passed to this function, except that time is omitted
 // if zero, and source is omitted if AddSource is false.
 //
 // The first argument is a list of currently open groups that contain the
 // Attr. It must not be retained or modified. ReplaceAttr is never called
 // for Group attributes, only their contents. For example, the attribute
 // list
 //
 //     Int("a", 1), Group("g", Int("b", 2)), Int("c", 3)
 //
 // results in consecutive calls to ReplaceAttr with the following arguments:
 //
 //     nil, Int("a", 1)
 //     []string{"g"}, Int("b", 2)
 //     nil, Int("c", 3)
 //
 // ReplaceAttr can be used to change the default keys of the built-in
 // attributes, convert types (for example, to replace a `time.Time` with the
 // integer seconds since the Unix epoch), sanitize personal information, or
 // remove attributes from the output.
 ReplaceAttr func(groups []string, a Attr) Attr
}

Let’s create a new Handler using NewTextHandler with AddSource and a log level of debug.

The handler can be passed into slog.New which accepts a Handler and returns a Logger instance. We can use this Logger instance to log using our custom logger.

package main

import (
 "log/slog"
 "os"
)

func main(){

 logHandler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
  Level: slog.LevelDebug,
  AddSource: true,

 })
 logger := slog.New(logHandler)

 logger.Debug("debug level")
 logger.Info("info level")
 logger.Warn("warn level")
 logger.Error("error level")
}

Run the software and you should see an updated input now also containing the source code that executes, and the Debug log.

time=2023-08-09T20:00:36.644+02:00 level=DEBUG source=/home/pp/development/blog/slog/main.go:16 msg="debug level"
time=2023-08-09T20:00:36.644+02:00 level=INFO source=/home/pp/development/blog/slog/main.go:17 msg="info level"
time=2023-08-09T20:00:36.644+02:00 level=WARN source=/home/pp/development/blog/slog/main.go:18 msg="warn level"
time=2023-08-09T20:00:36.644+02:00 level=ERROR source=/home/pp/development/blog/slog/main.go:19 msg="error level"

If you want JSON logs, simply replace NewTextHandler with NewJSONHandler and it will work.

Custom Attributes and Groups

If you look at the log lines, you can see for instance how source is a key value pair. This is known as an Attribute.

We can add custom attributes by passing extra attributes into the Log functions. Remember that they accepted a variadic amount of arguments?

The second argument in the Log functions is a variadic amount of arguments, these arguments are extra fields that we want to log, maybe the functions name, or the version of the application.

These fields are known as Attributes in slog. It is basically extra fields of information that we want to print along side the log message, the information should be related to the log.

These fields are very important in a large ecosystem of applications. An example would be if you have multiple deployments of the service, and when debugging something that has gone wrong in your monitoring system such as Prometheus, maybe the region of the running instance would be important etc.

There are two ways of passing attributes, either allowing Go to infer and calculate the type of data by simply passing the information in by order key value.

An example would be

logger.Debug("What's the meaning of life?", "answer", 42)

// Prints
{"time":"2023-08-09T20:08:53.443176536+02:00","level":"DEBUG","source":{"function":"main.main","file":"/home/pp/development/blog/slog/main.go","line":17},"msg":"What's the meaning of life?","answer":42}

See how it printed the attribute answer along with the Value?

This can be nice because the syntax or easy and simple. But for more efficient logging as mentioned in the docs, we can use LogAttributes.

We can create a new attribute by its function found in slog. Say we want to print answer as an Int. We would then instead do it like this

logger.Debug("What's the meaning of life?", slog.Int("answer", 42))

This will print the same thing, but it will be faster. The tradeoff is that it gets a little bit bloated fast.

Sometimes, we want to print a few related attributes. Slog allows us to group them by creating a group, it works in the same way as the level functions. We pass in the group name, followed by an variadic amount of attributes.

Here is an example of how we print out the Votes to my Pokemon rating list.

package main

import (
 "log/slog"
 "os"
)

func main(){

 logHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
  Level: slog.LevelDebug,
  AddSource: true,

 })
 logger := slog.New(logHandler)

 logger.Debug("Best Pokemon Rating",
  slog.Group("votes", 
   slog.Int("Picachu", 40),
   slog.Int("Mew", 24),
  ),
 )
}

The group fields will be grouped under the JSON field as an array.

{"time":"2023-08-09T20:18:06.205582248+02:00","level":"DEBUG","source":{"function":"main.main","file":"/home/pp/development/blog/slog/main.go","line":19},"msg":"Best Pokemon Rating","votes":{"Picachu":40,"Mew":24}}

This can be quiet nice and brings us to the next part. 

What if we want Default Attributes that ALL log messages should have?

We can add that to the Handler using the either of the WithAttrs which accepts an Array of Attributes that will always be present.

A great idea is to print Application information, configurations or the name of the service as these default attributes, or you know, the meaning of life.

package main

import (
 "log/slog"
 "os"
)

func main(){

 logHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
  Level: slog.LevelDebug,
  AddSource: true,

 }).WithAttrs([]slog.Attr{
  slog.Int("What's the meaning of life?", 42),
 })
 logger := slog.New(logHandler)

 logger.Debug("Test")
}

If you run that, you will see that the log line contains the attribute.

What is even more swell is that a Group is an Attribute itself, so we can push in my Pokemon votes as a default to each log line.

logHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
  Level: slog.LevelDebug,
  AddSource: true,

 }).WithAttrs([]slog.Attr{
  slog.Int("What's the meaning of life?", 42),
  slog.Group("Pokemon votes",
   slog.Int("Picachu", 40),
   slog.Int("Mew", 27),
  ),
 })

Replacing The Default Logger And Replacing Attributes

Right now, we are creating a Log instance that we use to print out logs instead of using the Default log from Slog.

This allows us to make these amazing customization, but now we need to pass this logger around in our software, which can become quite troublesome.

To set the default logger you can use

slog.SetDefault(logger)

Then we can get our amazing customized logger to apply globally instead of passing the logger around.

One last thing we might want to do is learn about ReplaceAttr which is a field when we create the Handler.

This allows us to replace Keys or Values from attributes. This can be quiet useful, for example what if we don’t want to print timestamps, but instead Unix timestamps?

Let us look at how we can do that,

The ReplaceAttr is a function that accepts an array of group names, and also the current attribute that is being worked on.

This attribute is a pointer, so we can modify it to match our needs.

Slog uses time as the key for when the log is being printed, I want to change that to date and unix time.

We can do this by simply checking if the attribute Key matches the time string, and replace the value.

ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr{
   // Match the key we want
   if a.Key == slog.TimeKey {
    a.Key = "date" // Rename time into date
    a.Value = slog.Int64Value(time.Now().Unix()) // Set it to a int64 unix time
   }
   return a
  },

That is all we need to make it work

package main

import (
 "log/slog"
 "os"
 "time"
)

func main(){

 logHandler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
  Level: slog.LevelDebug,
  AddSource: true,
  ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr{
   if a.Key == slog.TimeKey {
    // Parse it correctly
    a.Key = "date" // Rename time into date
    a.Value = slog.Int64Value(time.Now().Unix())
   }
   return a
  },
 }).WithAttrs([]slog.Attr{
  slog.Int("What's the meaning of life?", 42),
  slog.Group("Pokemon votes",
   slog.Int("Picachu", 40),
   slog.Int("Mew", 27),
  ),
 })

 logger := slog.New(logHandler)

 logger.Debug("Test")
 slog.SetDefault(logger)
 
 myLogFunc()
}

func myLogFunc() {
 slog.Info("Log from inside")
}

Try running the software, and you should see a nice unix timestamp called date being printed.

{"date":1691607523,"level":"INFO","source":{"function":"main.myLogFunc","file":"/home/pp/development/blog/slog/main.go","line":43},"msg":"Log from inside","What's the meaning of life?":42,"Pokemon votes":{"Picachu":40,"Mew":27}}

Conclusion

That is it for this short article.

In it, we have covered how to get started with Structured logging using Slog in Go.

We have learned about the log levels, the attributes, and how we can group attributes. 

We learn about default fields and how to replace the default logger with our customized logger.

Finally we looked at how we can replace values and keys.

I hope you enjoyed this article!