Structured logging

At the moment we’re outputting log entries from our code using the log.Printf() and log.Fatal() functions. A good example of this is the “starting server…” log entry that we print just before our server starts:

log.Printf("starting server on %s", *addr)

Both the log.Printf() and log.Fatal() functions output log entries using Go’s standard logger from the log package, which — by default — prefixes a message with the local date and time and writes out to the standard error stream (which should display in your terminal window).

$ go run ./cmd/web/
2024/03/18 11:29:23 starting server on :4000

For many applications, using the standard logger will be good enough, and there’s no need to do anything more complex.

But for applications which do a lot of logging, you may want to make the log entries easier to filter and work with. For example, you might want to distinguish between different severities of log entries (like informational and error entries), or to enforce a consistent structure for log entries so that they are easy for external programs or services to parse.

To support this, the Go standard library includes the log/slog package which lets you create custom structured loggers that output log entries in a set format. Each log entry includes the following things:

• A timestamp with millisecond precision.
• The severity level of the log entry (Debug, Info, Warn or Error).
• The log message (an arbitrary string value).
• Optionally, any number of key-value pairs (known as attributes) containing additional information.

Creating a structured logger

The code for creating a structured logger with the log/slog package can be a little bit confusing the first time you see it.

The key thing to understand is that all structured loggers have a structured logging handler associated with them (not to be confused with a HTTP handler), and it’s actually this handler that controls how log entries are formatted and where they are written to.

The code for creating a logger looks like this:

loggerHandler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{...})
logger := slog.New(loggerHandler)

In the first line of code we first use the slog.NewTextHandler() function to create the structured logging handler. This function accepts two arguments:

• The first argument is the write destination for the log entries. In the example above we’ve set it to os.Stdout, which means it will write log entries to the standard out stream.
• The second argument is a pointer to a slog.HandlerOptions struct , which you can use to customize the behavior of the handler. We’ll take a look at some of the available customizations at the end of this chapter. If you’re happy with the defaults and don’t want to change anything, you can pass nil as the second argument instead.

Then in the second line of code, we actually create the structured logger by passing the handler to the slog.New() function.

In practice, it’s more common to do all this in a single line of code:

logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{...}))

Using a structured logger

Once you’ve created a structured logger, you can then write a log entry at a specific severity level by calling the Debug(), Info(), Warn() or Error() methods on the logger. As an example, the following line of code:

logger.Info("request received")

Would result in a log entry that looks like this:

time=2024-03-18T11:29:23.000+00:00 level=INFO msg="request received"

The Debug(), Info(), Warn() or Error() methods are variadic methods which accept an arbitrary number of additional attributes ( key-value pairs). Like so:

logger.Info("request received", "method", "GET", "path", "/")

In this example, we’ve added two extra attributes to the log entry: the key "method" and value "GET", and the key "path" and value "/". Attribute keys must always be strings, but the values can be of any type. In this example, the log entry will look like this:

time=2024-03-18T11:29:23.000+00:00 level=INFO msg="request received" method=GET path=/

Adding structured logging to our application

OK, let’s go ahead and update our main.go file to use a structured logger instead of Go’s standard logger. Like so:

package main

import (
    "flag"
    "log/slog" // New import
    "net/http"
    "os" // New import
)

func main() {
    addr := flag.String("addr", ":4000", "HTTP network address")
    flag.Parse()

    // Use the slog.New() function to initialize a new structured logger, which
    // writes to the standard out stream and uses the default settings.
    logger := slog.New(slog.NewTextHandler(os.Stdout, nil))

    mux := http.NewServeMux()

    fileServer := http.FileServer(http.Dir("./ui/static/"))
    mux.Handle("GET /static/", http.StripPrefix("/static", fileServer))

    mux.HandleFunc("GET /{$}", home)
    mux.HandleFunc("GET /snippet/view/{id}", snippetView)
    mux.HandleFunc("GET /snippet/create", snippetCreate)
    mux.HandleFunc("POST /snippet/create", snippetCreatePost)

    // Use the Info() method to log the starting server message at Info severity
    // (along with the listen address as an attribute).
    logger.Info("starting server", "addr", *addr)

    err := http.ListenAndServe(*addr, mux)
    // And we also use the Error() method to log any error message returned by
    // http.ListenAndServe() at Error severity (with no additional attributes),
    // and then call os.Exit(1) to terminate the application with exit code 1.
    logger.Error(err.Error())
    os.Exit(1)
}

Alright… let’s try this out!

Go ahead and run the application, then open another terminal window and try to run it a second time. This should generate an error because the network address our server wants to listen on (":4000") is already in use.

The log output in your second terminal should look a bit like this:

$ go run ./cmd/web
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="starting server" addr=:4000
time=2024-03-18T11:29:23.000+00:00 level=ERROR msg="listen tcp :4000: bind: address already in use"
exit status 1

This is looking pretty good. We can see that the two log entries contain different information, but are formatted in the same overall way.

The first log entry has the severity level=INFO and message msg="starting server", along with the additional addr=:4000 attribute. In contrast, we see that the second log entry has the severity level=ERROR, the msg value contains the content of the error message, and there are no additional attributes.

Additional information

Safer attributes

Let’s say that you accidentally write some code where you forget to include either the key or value for an attribute. For example:

logger.Info("starting server", "addr") // Oops, the value for "addr" is missing

When this happens, the log entry will still be written but the attribute will have the key !BADKEY, like so:

time=2024-03-18T11:29:23.000+00:00 level=INFO msg="starting server" !BADKEY=addr

To avoid this happening and catch any problems at compile-time, you can use the slog.Any() function to create an attribute pair instead:

logger.Info("starting server", slog.Any("addr", ":4000"))

Or you can go even further and introduce some additional type safety by using the slog.String(), slog.Int(), slog.Bool(), slog.Time() and slog.Duration() functions to create attributes with a specific type of value.

logger.Info("starting server", slog.String("addr", ":4000"))

Whether you want to use these functions or not is up to you. The log/slog package is relatively new to Go (introduced in Go 1.21), and there isn’t much in the way of established best-practices or conventions around using it yet. But the trade-off is straightforward… using functions like slog.String() to create attributes is more verbose, but safer in sense that it reduces the risk of bugs in your application.

JSON formatted logs

The slog.NewTextHandler() function that we’ve used in this chapter creates a handler that writes plaintext log entries. But it’s possible to create a handler that writes log entries as JSON objects instead using the slog.NewJSONHandler() function. Like so:

logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))

When using the JSON handler, the log output will look similar to this:

{"time":"2024-03-18T11:29:23.00000000+00:00","level":"INFO","msg":"starting server","addr":":4000"}
{"time":"2024-03-18T11:29:23.00000000+00:00","level":"ERROR","msg":"listen tcp :4000: bind: address already in use"}

Minimum log level

As we’ve mentioned a couple of times, the log/slog package supports four severity levels: Debug, Info, Warn and Error in that order. Debug is the least severe level, and Error is the most severe.

By default, the minimum log level for a structured logger is Info. That means that any log entries with a severity less than Info — i.e. Debug level entries — will be silently discarded.

You can use the slog.HandlerOptions struct to override this and set the minimum level to Debug (or any other level) if you want:

logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
    Level: slog.LevelDebug,
}))

Caller location

You can also customize the handler so that it includes the filename and line number of the calling source code in the log entries, like so:

logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
    AddSource: true,
}))

The log entries will look similar to this, with the caller location recorded under the source key:

time=2024-03-18T11:29:23.000+00:00 level=INFO source=/home/alex/code/snippetbox/cmd/web/main.go:32 msg="starting server" addr=:4000

Decoupled logging

In this chapter we’ve set up our structured logger to write entries to os.Stdout — the standard out stream.

The big benefit of writing log entries to os.Stdout is that your application and logging are decoupled. Your application itself isn’t concerned with the routing or storage of the logs, and that can make it easier to manage the logs differently depending on the environment.

During development, it’s easy to view the log output because the standard out stream is displayed in the terminal.

In staging or production environments, you can redirect the stream to a final destination for viewing and archival. This destination could be on-disk files, or a logging service such as Splunk. Either way, the final destination of the logs can be managed by your execution environment independently of the application.

For example, we could redirect the standard out stream to a on-disk file when starting the application like so:

$ go run ./cmd/web >>/tmp/web.log

Concurrent logging

Custom loggers created by slog.New() are concurrency-safe. You can share a single logger and use it across multiple goroutines and in your HTTP handlers without needing to worry about race conditions.

That said, if you have multiple structured loggers writing to the same destination then you need to be careful and ensure that the destination’s underlying Write() method is also safe for concurrent use.