Go (golang) Slog Package
Overview
In Go (golang) release 1.21, the slog package will be added to the standard library. It includes many useful features such as structured logging as well as level logging. In this article, we will talk about the history of logging in Go, the challenges faced, and how the new slog
package will help address those challenges.
Target Audience
This article is aimed at developers that have minimum experience with Go.
In this article, we'll cover the following topics:
- Introduce the Slog package that is released in Go 1.21
- Cover the major features being introduced with this logging package
- See variations of how to use the logger in the
slog
package
History of Logging in Go
When Go was first released in 2012 to the public, it shipped with the very simple log package. While it was useful in a limited fashion, it lacked most of what was needed for enterprise applications.
I think many of us in the Go community expected a better logger to appear, and some did, but as of 2017, the standard library had still not included any more robust options for logging. As a result, many community members got together with the idea of solving this problem. As you can see by the document that was started and shared, the effort failed. Mostly, it simply failed because of a lack of agreement on fundamentally what a logger should even do. Should it do level logging? Should it be structured?
As a result, many third party packages evolved over time that addressed those issues in various capacities, but the standard library still only had the basic functionality included.
Thankfully, the wait is over, and Go has officially shipped the slog package!
The Basics
Unlike the basic log
package, there are no Print
, Printf
, or Println
functions. This is due to the fact that all messages need to be of a specific type, or level
. The current levels are Info
, Warn
, Error
, and Debug
. Each of them have a corresponding function in the library and can be called as follows:
package main
import "log/slog"
func main() {
slog.Info("hello gophers")
slog.Warn("be warned!")
slog.Error("this is broken")
slog.Debug("show some debugging output")
}
$ go run .
2024/02/16 08:42:59 INFO hello gophers
2024/02/16 08:42:59 WARN be warned!
2024/02/16 08:42:59 ERROR this is broken
--------------------------------------------------------------------------------
Go Version: go1.22.0
Notice that the Debug
statement did not print? That is because the default level of the logger is Info
. We will see later in this article how to enable the DEBUG
statements to be logged to the output.
Creating a Logger
While you can use the basic logging methods directly, it's more likely you'll want to have more control over how your logger works. As such, you will need to create a logger to work with.
Here we create a logger, and we tell it that we want to use JSON
as our output:
package main
import (
"log/slog"
"os"
)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
logger.Info("hello gophers")
logger.Warn("be warned!")
logger.Error("this is broken")
}
$ go run .
{"time":"2024-02-16T08:43:00.412408-06:00","level":"INFO","msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.412507-06:00","level":"WARN","msg":"be warned!"}
{"time":"2024-02-16T08:43:00.412509-06:00","level":"ERROR","msg":"this is broken"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Default Logger
By default, The slog
package uses a default logger. You may want to actually create your own logger with specific options to use, and then set the default logger to use those settings everywhere.
The first step is to create your logger, then set it to the default logger. This will allow all other packages in your program to use these log settings.
package main
import (
"log"
"log/slog"
"os"
"training/store"
)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
logger.Info("hello gophers")
logger.Warn("be warned!")
logger.Error("this is broken")
// Set the logger for the application
slog.SetDefault(logger)
s := store.New()
// we can now use the standard logger again as it uses the options we set above
slog.Info("new store created", "store-id", s.ID)
// the standard logger now uses the new logger as well
log.Println("I'm log.println, look at me!")
}
Now that we have set the default logger, we can use the standard slog
package to log from any package that we create and import, and it will use the settings we just applied. Note that it also updates the standard logger from the log
package, which means that all future log.Print
, log.Println
, and log.Printf
statements use the new logger that was applied.
package store
import (
"log/slog"
"math/rand"
)
type Store struct {
ID int
}
func New() *Store {
s := &Store{
ID: rand.Intn(100),
}
slog.Info("creating store", "store-id", s.ID)
return s
}
$ go run .
{"time":"2024-02-16T08:42:59.905703-06:00","level":"INFO","msg":"hello gophers"}
{"time":"2024-02-16T08:42:59.905827-06:00","level":"WARN","msg":"be warned!"}
{"time":"2024-02-16T08:42:59.905828-06:00","level":"ERROR","msg":"this is broken"}
{"time":"2024-02-16T08:42:59.905842-06:00","level":"INFO","msg":"creating store","store-id":32}
{"time":"2024-02-16T08:42:59.905854-06:00","level":"INFO","msg":"new store created","store-id":32}
{"time":"2024-02-16T08:42:59.905879-06:00","level":"INFO","msg":"I'm log.println, look at me!"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Notice that that even though we are just using the slog.Info
function in the store
package, it still uses the logger we set from the main
function in the main
package. This feature allows us to set the logger once for our application, and any future calls from either the log
or slog
package will have properly formatted output.
Levels
As stated before, there are four levels of logging, Info
, Warn
, Error
, and Debug
. When creating your logger, you can set the level at which you want information to be logged.
To change the logging level, we can set it with the
package main
import (
"log/slog"
"os"
)
func main() {
// Pass the loggingLevel to the new logger being created so we can change it later at any time
logger := slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelDebug}))
logger.Info("hello gophers")
logger.Warn("be warned!")
logger.Error("this is broken")
logger.Debug("be warned!")
}
$ go run .
{"time":"2024-02-16T08:43:00.556027-06:00","level":"INFO","msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.556125-06:00","level":"WARN","msg":"be warned!"}
{"time":"2024-02-16T08:43:00.556126-06:00","level":"ERROR","msg":"this is broken"}
{"time":"2024-02-16T08:43:00.556128-06:00","level":"DEBUG","msg":"be warned!"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
It is important to note that depending on the level, some messages may not be logged out. For instance, Debug
messages are ONLY logged out if the logger level is set to slog.LevelDebug
.
Level Variable
It may be useful to turn on and off debugging while your program is running. While this does require more setup, and you'll need the ability to change this option via some type of API at runtime, the following setup would enable you do to that via a variable.
package main
import (
"log/slog"
"os"
)
func main() {
// create a logging level variable
// the level is Info by default
var loggingLevel = new(slog.LevelVar)
// Pass the loggingLevel to the new logger being created so we can change it later at any time
logger := slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: loggingLevel}))
loggingLevel.Set(slog.LevelDebug)
logger.Info("hello gophers")
logger.Warn("be warned!")
logger.Error("this is broken")
logger.Debug("be warned!")
}
$ go run .
{"time":"2024-02-16T08:43:00.051552-06:00","level":"INFO","msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.051661-06:00","level":"WARN","msg":"be warned!"}
{"time":"2024-02-16T08:43:00.051663-06:00","level":"ERROR","msg":"this is broken"}
{"time":"2024-02-16T08:43:00.051665-06:00","level":"DEBUG","msg":"be warned!"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Grouping Values
The logger also allows you to group
information for logging. For example, for an http request, you may want to log information specific to that request all in the same group.
Here is an example of using the Group
feature of the logger with a JSON
handler:
package main
import (
"log"
"log/slog"
"net/http"
"os"
)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
slog.SetDefault(logger)
log.Println("program started")
r, err := http.Get("https://www.gopherguides.com")
if err != nil {
slog.Error("error retrieving site", "err", err)
}
slog.Info("success", slog.Group("request", "method", r.Request.Method, "url", r.Request.URL.String()))
}
$ go run .
{"time":"2024-02-16T08:43:00.962396-06:00","level":"INFO","msg":"program started"}
{"time":"2024-02-16T08:43:01.110628-06:00","level":"INFO","msg":"success","request":{"method":"GET","url":"https://www.gopherguides.com"}}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Notice that the output for request
is now a new message containing the method
and the url
values.
Improving Log Performance
Logging can be an expensive operation in your application. Much of that expense is due to the allocations created to hold the values before logging the output. That expense can be avoided however, if you use the convenience methods for setting key/value pairs when logging. These methods are slog.Int
, slog.String
, slog.Bool
and slog.Any
.
package main
import (
"log"
"log/slog"
"net/http"
"os"
)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
slog.SetDefault(logger)
log.Println("program started")
r, err := http.Get("https://www.gopherguides.com")
if err != nil {
slog.Error("error retrieving site", slog.String("err", err.Error()))
}
slog.Info("success",
slog.Group(
"request",
slog.String("method", r.Request.Method),
slog.String("url", r.Request.URL.String()),
))
}
$ go run .
{"time":"2024-02-16T08:43:01.075436-06:00","level":"INFO","msg":"program started"}
{"time":"2024-02-16T08:43:01.245242-06:00","level":"INFO","msg":"success","request":{"method":"GET","url":"https://www.gopherguides.com"}}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Notice that the output didn't change, but using the Attr
helpers will avoid allocations when logging which will improve the performance of your application.
Customizing Log Behavior
There may be times that you want to control how values are output by the logger. One of those times might be if you want to sanitize a value, perhaps a password. You can do this by implementing the slog.LogValuer
interface.
Let's look at the following program. Currently it will output all the values for the logged data struct, even the sensitive ones such as password.
package main
import (
"log"
"log/slog"
"os"
)
type User struct {
ID int
Username string
Password string
}
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
slog.SetDefault(logger)
log.Println("program started")
u := User{ID: 10, Username: "admin", Password: "abc123"}
log.Println(u)
}
$ go run .
{"time":"2024-02-16T08:43:00.266943-06:00","level":"INFO","msg":"program started"}
{"time":"2024-02-16T08:43:00.267105-06:00","level":"INFO","msg":"{10 admin abc123}"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Currently, sensitive data can be leaked out to the log. If we implement the slog.LogValuer
interface, we can prevent our sensitive data from leaking out to the logs.
package main
import (
"log"
"log/slog"
"os"
)
type User struct {
ID int
Username string
Password string
}
func (u User) LogValue() slog.Value {
return slog.GroupValue(
slog.Int("ID", u.ID),
slog.String("username", u.Username),
slog.String("password", "TOKEN_REDACTED"),
)
}
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
slog.SetDefault(logger)
log.Println("program started")
u := User{ID: 10, Username: "admin", Password: "abc123"}
// the log package does NOT detect the `LogValuer` interface
log.Println(u)
// You must use the slog package to detect the `Log.Valuer`
slog.Info("user", "user", u)
}
$ go run .
{"time":"2024-02-16T08:43:00.122423-06:00","level":"INFO","msg":"program started"}
{"time":"2024-02-16T08:43:00.12258-06:00","level":"INFO","msg":"{10 admin abc123}"}
{"time":"2024-02-16T08:43:00.122582-06:00","level":"INFO","msg":"user","user":{"ID":10,"username":"admin","password":"TOKEN_REDACTED"}}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Note that while the standard log
package will work well in most cases with the new slog
package, it does NOT detect the slog.LogValuer
interface and therefor should be avoided if you need that functinality.
Adding Source File Information
Many times, the hardest part of finding a bug is determining which file and which line the log message originated from. In the slog
package, this is simplified by setting the AddSource
option when creating the handler options.
package main
import (
"log/slog"
"os"
"training/store"
)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{AddSource: true}))
// Set the logger for the application
slog.SetDefault(logger)
slog.Info("hello gophers")
slog.Warn("be warned!")
slog.Error("this is broken")
_ = store.New()
}
$ go run .
{"time":"2024-02-16T08:43:00.697306-06:00","level":"INFO","source":{"function":"main.main","file":"./main.go","line":14},"msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.69744-06:00","level":"WARN","source":{"function":"main.main","file":"./main.go","line":15},"msg":"be warned!"}
{"time":"2024-02-16T08:43:00.697444-06:00","level":"ERROR","source":{"function":"main.main","file":"./main.go","line":16},"msg":"this is broken"}
{"time":"2024-02-16T08:43:00.697447-06:00","level":"INFO","source":{"function":"training/store.New","file":"./store/store.go","line":8},"msg":"starting store"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Notice that you get the fully qualified path. This is likely not what you want, so we can also use the ReplaceAttr
option as well to create the desired output:
package main
import (
"log/slog"
"os"
"path/filepath"
"training/store"
)
func main() {
replacer := func(groups []string, a slog.Attr) slog.Attr {
if a.Key == slog.SourceKey {
source := a.Value.Any().(*slog.Source)
source.File = filepath.Base(source.File)
}
return a
}
logger := slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{AddSource: true, ReplaceAttr: replacer}))
// Set the logger for the application
slog.SetDefault(logger)
slog.Info("hello gophers")
slog.Warn("be warned!")
slog.Error("this is broken")
_ = store.New()
}
$ go run .
{"time":"2024-02-16T08:43:00.62628-06:00","level":"INFO","source":{"function":"main.main","file":"main.go","line":24},"msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.626472-06:00","level":"WARN","source":{"function":"main.main","file":"main.go","line":25},"msg":"be warned!"}
{"time":"2024-02-16T08:43:00.626476-06:00","level":"ERROR","source":{"function":"main.main","file":"main.go","line":26},"msg":"this is broken"}
{"time":"2024-02-16T08:43:00.626479-06:00","level":"INFO","source":{"function":"training/store.New","file":"store.go","line":8},"msg":"starting store"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Relative Source File Information
While the previous examples work, having the absolute path to a file or just the file name isn't exactly what we want. Typically, you want the path to the file from the root of the project. To do that, we can add just a few extra lines to our replacer
function to strip out the current working directory.
package main
import (
"log"
"log/slog"
"os"
"strings"
"training/store"
)
func main() {
// we only want to calculate the working directory once
// not every time we log
wd, err := os.Getwd()
if err != nil {
log.Fatal("unable to determine working directory")
}
replacer := func(groups []string, a slog.Attr) slog.Attr {
if a.Key == slog.SourceKey {
source := a.Value.Any().(*slog.Source)
// remove current working directory and only leave the relative path to the program
if file, ok := strings.CutPrefix(source.File, wd); ok {
source.File = file
}
}
return a
}
logger := slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{AddSource: true, ReplaceAttr: replacer}))
// Set the logger for the application
slog.SetDefault(logger)
slog.Info("hello gophers")
slog.Warn("be warned!")
slog.Error("this is broken")
_ = store.New()
}
$ go run .
{"time":"2024-02-16T08:43:00.844151-06:00","level":"INFO","source":{"function":"main.main","file":"/main.go","line":35},"msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.844408-06:00","level":"WARN","source":{"function":"main.main","file":"/main.go","line":36},"msg":"be warned!"}
{"time":"2024-02-16T08:43:00.844412-06:00","level":"ERROR","source":{"function":"main.main","file":"/main.go","line":37},"msg":"this is broken"}
{"time":"2024-02-16T08:43:00.844415-06:00","level":"INFO","source":{"function":"training/store.New","file":"/store/store.go","line":8},"msg":"starting store"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Source Only with Debug
Since adding source to the log output can not only degrade system performance, its just plain noisy a lot of times. As such, we can change our program to only allow for the source to be present if we our logging level is set to debug
. For this example, we'll use an environment variable to control the change.
package main
import (
"log"
"log/slog"
"os"
"strings"
"training/store"
)
func main() {
var loggingLevel = new(slog.LevelVar)
// we only want to calculate the working directory once
// not every time we log
wd, err := os.Getwd()
if err != nil {
log.Fatal("unable to determine working directory")
}
replacer := func(groups []string, a slog.Attr) slog.Attr {
if a.Key == slog.SourceKey {
source := a.Value.Any().(*slog.Source)
// remove current working directory and only leave the relative path to the program
if file, ok := strings.CutPrefix(source.File, wd); ok {
source.File = file
}
}
return a
}
options := &slog.HandlerOptions{
Level: loggingLevel,
ReplaceAttr: replacer,
}
// if debug is present, turn on logging level and source for logs
if os.Getenv("loglevel") == "debug" {
loggingLevel.Set(slog.LevelDebug)
options.AddSource = true
}
logger := slog.New(slog.NewJSONHandler(os.Stderr, options))
// Set the logger for the application
slog.SetDefault(logger)
slog.Info("hello gophers")
slog.Warn("be warned!")
slog.Error("this is broken")
slog.Debug("this is a debug")
_ = store.New()
}
Here is the output without source and no debug:
$ go run .
{"time":"2024-02-16T08:43:00.485333-06:00","level":"INFO","msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.485549-06:00","level":"WARN","msg":"be warned!"}
{"time":"2024-02-16T08:43:00.485551-06:00","level":"ERROR","msg":"this is broken"}
{"time":"2024-02-16T08:43:00.485553-06:00","level":"INFO","msg":"starting store"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Here is the output with debug turned on (environment variable loglevel
set to debug
:
$ go run .
{"time":"2024-02-16T08:43:00.338433-06:00","level":"INFO","source":{"function":"main.main","file":"/main.go","line":47},"msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.338616-06:00","level":"WARN","source":{"function":"main.main","file":"/main.go","line":48},"msg":"be warned!"}
{"time":"2024-02-16T08:43:00.33862-06:00","level":"ERROR","source":{"function":"main.main","file":"/main.go","line":49},"msg":"this is broken"}
{"time":"2024-02-16T08:43:00.338623-06:00","level":"DEBUG","source":{"function":"main.main","file":"/main.go","line":50},"msg":"this is a debug"}
{"time":"2024-02-16T08:43:00.338626-06:00","level":"INFO","source":{"function":"training/store.New","file":"/store/store.go","line":8},"msg":"starting store"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
With
In a larger code base, it's very common to have several subsystems. In those cases, it's common to pass the logger to the constructor for those systems, and then those constructors can use the With
method to identify all logs that came from those systems. This relieves the need to identify in every call to the logger what the context
of the system was when the logging occurred. This is very helpful when parsing and searching logs.
package main
import (
"log/slog"
"os"
"training/store"
)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stderr, nil))
// Set the logger for the application
slog.SetDefault(logger)
slog.Info("hello gophers")
slog.Warn("be warned!")
slog.Error("this is broken")
_ = store.New(logger)
}
$ go run .
{"time":"2024-02-16T08:43:00.769448-06:00","level":"INFO","msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.769556-06:00","level":"WARN","msg":"be warned!"}
{"time":"2024-02-16T08:43:00.769558-06:00","level":"ERROR","msg":"this is broken"}
{"time":"2024-02-16T08:43:00.76956-06:00","level":"INFO","msg":"starting store","sys":"store"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Putting it all together
Now that we have seen several different ways to use the new slog
package, here is an example of what a production level logger configuration might look like.
Main Code:
package main
import (
"log"
"log/slog"
"os"
"strings"
"training/store"
)
func main() {
var loggingLevel = new(slog.LevelVar)
wd, err := os.Getwd()
if err != nil {
log.Fatal("unable to determine working directory")
}
replacer := func(groups []string, a slog.Attr) slog.Attr {
if a.Key == slog.SourceKey {
source := a.Value.Any().(*slog.Source)
if file, ok := strings.CutPrefix(source.File, wd); ok {
source.File = file
}
}
return a
}
options := &slog.HandlerOptions{
Level: loggingLevel,
ReplaceAttr: replacer,
}
if os.Getenv("loglevel") == "debug" {
loggingLevel.Set(slog.LevelDebug)
options.AddSource = true
}
logger := slog.New(slog.NewJSONHandler(os.Stderr, options))
slog.SetDefault(logger)
slog.Info("hello gophers")
slog.Warn("be warned!")
slog.Error("this is broken")
_ = store.New(logger)
}
Store Code:
package store
import "log/slog"
type Store struct {
log *slog.Logger
}
func New(log *slog.Logger) *Store {
s := &Store{
log: log.With("sys", "store"),
}
s.log.Info("starting store")
s.log.Debug("using custom logger")
return s
}
$ go run .
{"time":"2024-02-16T08:43:00.194963-06:00","level":"INFO","msg":"hello gophers"}
{"time":"2024-02-16T08:43:00.195116-06:00","level":"WARN","msg":"be warned!"}
{"time":"2024-02-16T08:43:00.195119-06:00","level":"ERROR","msg":"this is broken"}
{"time":"2024-02-16T08:43:00.195122-06:00","level":"INFO","msg":"starting store","sys":"store"}
--------------------------------------------------------------------------------
Go Version: go1.22.0
Summary
The slog
package has added many great convenience features to the standard library that bring it up to date with most modern logging philosophies. Making use of these features will allow you to create enterprise applications in the future.
More Articles
Hype Quick Start Guide
Overview
This article covers the basics of quickly writing a technical article using Hype.
Writing Technical Articles using Hype
Overview
Creating technical articles can be painful when they include code samples and output from running programs. Hype makes this easy to not only create those articles, but ensure that all included content for the code, etc stays up to date. In this article, we will show how to set up Hype locally, create hooks for live reloading and compiling of your documents, as well as show how to dynamically include code and output directly to your documents.
The Slices Package
Overview
In release 1.21, the slices package will be officially added to the standard library. It includes many useful functions for sorting, managing, and searching slices. In this article, we will cover the more commonly used functions included in the Slices package.