Let's Go Further Structured Logging and Error Handling › Structured JSON Log Entries
Previous · Contents · Next
Chapter 10.1.

Structured JSON Log Entries

At the moment, all of our log entries are simple free-form messages prefixed by the current date and time, written to the standard out stream. A good example of these are the log entries that we see when we start the API:

$ go run ./cmd/api
2021/04/09 19:43:31 database connection pool established
2021/04/09 19:43:31 starting development server on :4000

For many applications this simple style of logging will be good enough, and there’s no need to introduce additional complexity to your project.

But for applications which do a lot of logging, it can often be useful to enforce a consistent structure and format for your log entries. This can help make it easier to distinguish between different types of log entry (like informational and error entries), easier to search and filter log entries, and simpler to integrate your logs with third-party analysis and monitoring systems.

So in this chapter we’re going demonstrate how to adapt our application so that log entries are written in a structured JSON format, similar to this:

{"level":"INFO","time":"2020-12-16T10:53:35Z","message":"starting server","properties":{"addr":":4000","env":"development"}}

Essentially, each log entry will be a single JSON object containing the following key/value pairs:

Key Description
level A code indicating the severity of the log entry. In this project we will use the following three severity levels, ordered from least to most severe:
- INFO (least severe)
- ERROR
- FATAL (most severe)
time The UTC time that the log entry was made with second precision.
message A string containing the free-text information or error message.
properties Any additional information relevant to the log entry in string key/value pairs (optional).
trace A stack trace for debugging purposes (optional).

Creating a custom logger

To implement this in our API, we’re going to create our own custom Logger type which writes structured log entries in JSON format.

We’ll implement some convenience methods on Logger, such as PrintInfo() and PrintError(), in order to make it easy to write log entries with a specific level from our application in a single command. And we’ll also design the logger so that only entries at or above a certain minimum severity level are actually logged — so if you only want to record ERROR and FATAL messages (and not INFO messages), then that is easy to do.

If you’re following along, go ahead and create a new internal/jsonlog package like so:

$ mkdir internal/jsonlog
$ touch internal/jsonlog/jsonlog.go

And then add the following code:

File: internal/jsonlog/jsonlog.go
package jsonlog

import (
    "encoding/json"
    "io"
    "os"
    "runtime/debug"
    "sync"
    "time"
)

// Define a Level type to represent the severity level for a log entry.
type Level int8

// Initialize constants which represent a specific severity level. We use the iota
// keyword as a shortcut to assign successive integer values to the constants.
const (
    LevelInfo  Level = iota // Has the value 0.
    LevelError              // Has the value 1.
    LevelFatal              // Has the value 2.
    LevelOff                // Has the value 3.
)

// Return a human-friendly string for the severity level.
func (l Level) String() string {
    switch l {
    case LevelInfo:
        return "INFO"
    case LevelError:
        return "ERROR"
    case LevelFatal:
        return "FATAL"
    default:
        return ""
    }
}

// Define a custom Logger type. This holds the output destination that the log entries
// will be written to, the minimum severity level that log entries will be written for,
// plus a mutex for coordinating the writes.
type Logger struct {
    out      io.Writer
    minLevel Level
    mu       sync.Mutex
}

// Return a new Logger instance which writes log entries at or above a minimum severity
// level to a specific output destination.
func New(out io.Writer, minLevel Level) *Logger {
    return &Logger{
        out:      out,
        minLevel: minLevel,
    }
}

// Declare some helper methods for writing log entries at the different levels. Notice
// that these all accept a map as the second parameter which can contain any arbitrary
// 'properties' that you want to appear in the log entry.
func (l *Logger) PrintInfo(message string, properties map[string]string) {
    l.print(LevelInfo, message, properties)
}

func (l *Logger) PrintError(err error, properties map[string]string) {
    l.print(LevelError, err.Error(), properties)
}

func (l *Logger) PrintFatal(err error, properties map[string]string) {
    l.print(LevelFatal, err.Error(), properties)
    os.Exit(1) // For entries at the FATAL level, we also terminate the application.
}

// Print is an internal method for writing the log entry.
func (l *Logger) print(level Level, message string, properties map[string]string) (int, error) {
    // If the severity level of the log entry is below the minimum severity for the
    // logger, then return with no further action.
    if level < l.minLevel {
        return 0, nil
    }

    // Declare an anonymous struct holding the data for the log entry.
    aux := struct {
        Level      string            `json:"level"`
        Time       string            `json:"time"`
        Message    string            `json:"message"`
        Properties map[string]string `json:"properties,omitempty"`
        Trace      string            `json:"trace,omitempty"`
    }{
        Level:      level.String(),
        Time:       time.Now().UTC().Format(time.RFC3339),
        Message:    message,
        Properties: properties,
    }

    // Include a stack trace for entries at the ERROR and FATAL levels.
    if level >= LevelError {
        aux.Trace = string(debug.Stack())
    }

    // Declare a line variable for holding the actual log entry text.
    var line []byte

    // Marshal the anonymous struct to JSON and store it in the line variable. If there
    // was a problem creating the JSON, set the contents of the log entry to be that
    // plain-text error message instead.
    line, err := json.Marshal(aux)
    if err != nil {
        line = []byte(LevelError.String() + ": unable to marshal log message: " + err.Error())
    }

    // Lock the mutex so that no two writes to the output destination can happen
    // concurrently. If we don't do this, it's possible that the text for two or more
    // log entries will be intermingled in the output.
    l.mu.Lock()
    defer l.mu.Unlock()

    // Write the log entry followed by a newline.
    return l.out.Write(append(line, '\n'))
}

// We also implement a Write() method on our Logger type so that it satisfies the 
// io.Writer interface. This writes a log entry at the ERROR level with no additional 
// properties.
func (l *Logger) Write(message []byte) (n int, err error) {
    return l.print(LevelError, string(message), nil)
}

Essentially, our Logger type is a fairly thin wrapper around an io.Writer. We have some helper methods like PrintInfo() and PrintError() which accept some data for the log entry, encode this data to JSON, and then write it to the io.Writer.

The two most interesting things to point out in this code are our use of the iota enumerator to create the log levels and a sync.Mutex to coordinate the writes.

You can use iota to easily assign successive integer values to a set of integer constants. It starts at zero, and increments by 1 for every constant declaration, resetting to 0 when the word const appears in the code again. The way that we’ve used this means that each of our severity levels has an integer value, with the more severe levels having a higher value.

We’re also using a sync.Mutex (a mutual exclusion lock) to prevent our Logger instance making multiple writes concurrently. Without this mutex lock, it’s possible that the content of multiple log entries would be written at exactly the same time and be mixed up in the output, rather than each entry being written in full on its own line.

Now that’s in place, let’s update our cmd/api/main.go file to create a new Logger instance and then use it in our code. We’ll also add it to our application struct, so that it’s available as a dependency to all our handlers and helpers.

Like so:

File: cmd/api/main.go
package main

import (
    "context"
    "database/sql"
    "flag"
    "fmt"
    "net/http"
    "os"
    "time"

    "greenlight.alexedwards.net/internal/data"
    "greenlight.alexedwards.net/internal/jsonlog" // New import

    _ "github.com/lib/pq"
)

...

// Change the logger field to have the type *jsonlog.Logger, instead of
// *log.Logger.
type application struct {
    config config
    logger *jsonlog.Logger
    models data.Models
}

func main() {
    var cfg config

    flag.IntVar(&cfg.port, "port", 4000, "API server port")
    flag.StringVar(&cfg.env, "env", "development", "Environment (development|staging|production)")

    flag.StringVar(&cfg.db.dsn, "db-dsn", os.Getenv("GREENLIGHT_DB_DSN"), "PostgreSQL DSN")

    flag.IntVar(&cfg.db.maxOpenConns, "db-max-open-conns", 25, "PostgreSQL max open connections")
    flag.IntVar(&cfg.db.maxIdleConns, "db-max-idle-conns", 25, "PostgreSQL max idle connections")
    flag.StringVar(&cfg.db.maxIdleTime, "db-max-idle-time", "15m", "PostgreSQL max connection idle time")

    flag.Parse()

    // Initialize a new jsonlog.Logger which writes any messages *at or above* the INFO
    // severity level to the standard out stream.
    logger := jsonlog.New(os.Stdout, jsonlog.LevelInfo)

    db, err := openDB(cfg)
    if err != nil {
        // Use the PrintFatal() method to write a log entry containing the error at the
        // FATAL level and exit. We have no additional properties to include in the log
        // entry, so we pass nil as the second parameter.
        logger.PrintFatal(err, nil)
    }

    defer db.Close()
    // Likewise use the PrintInfo() method to write a message at the INFO level.
    logger.PrintInfo("database connection pool established", nil)

    app := &application{
        config: cfg,
        logger: logger,
        models: data.NewModels(db),
    }

    srv := &http.Server{
        Addr:         fmt.Sprintf(":%d", cfg.port),
        Handler:      app.routes(),
        IdleTimeout:  time.Minute,
        ReadTimeout:  10 * time.Second,
        WriteTimeout: 30 * time.Second,
    }

    // Again, we use the PrintInfo() method to write a "starting server" message at the
    // INFO level. But this time we pass a map containing additional properties (the
    // operating environment and server address) as the final parameter.
    logger.PrintInfo("starting server", map[string]string{
        "addr": srv.Addr,
        "env":  cfg.env,
    })

    err = srv.ListenAndServe()
    // Use the PrintFatal() method to log the error and exit.
    logger.PrintFatal(err, nil)
}

...

We’ll also need to update the logError() helper in our cmd/api/errors.go file to use our new Logger instance. One of the nice things here is that it’s simple to include additional information as properties when logging the error.

If you’re following along, go ahead and update the logError() method so that it records the request URL and method alongside the error message. Like so:

File: cmd/api/errors.go
package main

...

func (app *application) logError(r *http.Request, err error) {
    // Use the PrintError() method to log the error message, and include the current 
    // request method and URL as properties in the log entry.
    app.logger.PrintError(err, map[string]string{
        "request_method": r.Method,
        "request_url":    r.URL.String(),
    })
}

...

At this point, if you restart the application you should now see two INFO level log entries in JSON format like so:

$ go run ./cmd/api
{"level":"INFO","time":"2021-04-10T08:08:36Z","message":"database connection pool established"}
{"level":"INFO","time":"2021-04-10T08:08:36Z","message":"starting server","properties":{"addr":":4000","env":"development"}}

Notice how in the second log entry the additional properties have been included in a nested JSON object?

If you like, you can also try opening a second terminal window and starting another instance of the API listening on the same port. This should result in a FATAL log entry and stack trace being printed, followed by the application immediately exiting. Similar to this:

$ go run ./cmd/api
{"level":"INFO","time":"2021-04-10T08:09:53Z","message":"database connection pool established"}
{"level":"INFO","time":"2021-04-10T08:09:53Z","message":"starting server","properties":{"addr":":4000","env":"development"}}
{"level":"FATAL","time":"2021-04-10T08:09:53Z","message":"listen tcp :4000: bind: address already in use","trace":"..."}
exit status 1

Additional Information

Integration with the http.Server error log

It’s important to be aware that Go’s http.Server may also write its own log messages relating to things like unrecovered panics, or problems accepting and writing to HTTP connections.

By default, it writes these messages to the standard logger — which means they will be written to the standard error stream (instead of standard out like our other log messages), and they won’t be in our nice new JSON format.

If you want everything logged in one place, in the same format, then that’s obviously a problem.

Unfortunately, you can’t set http.Server to use our new Logger type directly. Instead, you will need to leverage the fact that our Logger satisfies the io.Writer interface (thanks to the Write() method that we added to it), and set http.Server to use a regular log.Logger instance from the standard library which writes to our own Logger as the target destination.

It’s simpler than it sounds. All you have to do is something like this:

func main() {

    ...

    // Initialize the custom logger.
    logger := jsonlog.New(os.Stdout, jsonlog.LevelInfo)

    ...

    srv := &http.Server{
        Addr:         fmt.Sprintf(":%d", cfg.port),
        Handler:      app.routes(),
        // Create a new Go log.Logger instance with the log.New() function, passing in 
        // our custom Logger as the first parameter. The "" and 0 indicate that the
        // log.Logger instance should not use a prefix or any flags.
        ErrorLog:     log.New(logger, "", 0),
        IdleTimeout:  time.Minute,
        ReadTimeout:  10 * time.Second,
        WriteTimeout: 30 * time.Second,
    }

    ...
}

With that set up, any log messages that http.Server writes will be passed to our Logger.Write() method, which in turn will output a log entry in JSON format at the ERROR level.

Third-party logging packages

If you don’t want to implement your own custom logger, like we have in this chapter, then there is a plethora of third-party packages available which implement structured logging in JSON (and other) formats.

If I had to recommend one, it would be zerolog. It has a nice interface, and a good range of customization options. It’s also designed to be very fast and cheap in terms of memory allocations when writing log entries, so if your application is doing a lot of logging (i.e. more than just occasional information and error messages) then it may be a sensible choice.