Leveled logging

Chapter 3.2.

At the moment in our main.go file we’re outputting log messages using the log.Printf() and log.Fatal() functions.

Both these functions output messages via Go’s standard logger, which — by default — prefixes messages with the local date and time and writes them to the standard error stream (which should display in your terminal window). The log.Fatal() function will also call os.Exit(1) after writing the message, causing the application to immediately exit.

In our application, we can break apart our log messages into two distinct types — or levels. The first type is informational messages (like "Starting server on :4000") and the second type is error messages.

log.Printf("Starting server on %s", *addr) // Information message
err := http.ListenAndServe(*addr, mux)
log.Fatal(err) // Error message

Let’s improve our application by adding some leveled logging capability, so that information and error messages are managed slightly differently. Specifically:

We will prefix informational messages with "INFO" and output the message to standard out (stdout).
We will prefix error messages with "ERROR" and output them to standard error (stderr), along with the relevant file name and line number that called the logger (to help with debugging).

There are a couple of different ways to do this, but a simple and clear approach is to use the log.New() function to create two new custom loggers.

Open up your main.go file and update it as follows:

File: cmd/web/main.go

package main

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

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

    // Use log.New() to create a logger for writing information messages. This takes
    // three parameters: the destination to write the logs to (os.Stdout), a string
    // prefix for message (INFO followed by a tab), and flags to indicate what
    // additional information to include (local date and time). Note that the flags
    // are joined using the bitwise OR operator |.
    infoLog := log.New(os.Stdout, "INFO\t", log.Ldate|log.Ltime)

    // Create a logger for writing error messages in the same way, but use stderr as
    // the destination and use the log.Lshortfile flag to include the relevant
    // file name and line number.
    errorLog := log.New(os.Stderr, "ERROR\t", log.Ldate|log.Ltime|log.Lshortfile)

    mux := http.NewServeMux()

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

    mux.HandleFunc("/", home)
    mux.HandleFunc("/snippet/view", snippetView)
    mux.HandleFunc("/snippet/create", snippetCreate)

    // Write messages using the two new loggers, instead of the standard logger.
    infoLog.Printf("Starting server on %s", *addr)
    err := http.ListenAndServe(*addr, mux)
    errorLog.Fatal(err)
}

Alright… let’s try these 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
INFO    2022/01/29 16:00:50 Starting server on :4000
ERROR   2022/01/29 16:00:50 main.go:37: listen tcp :4000: bind: address already in use
exit status 1

Notice how the two messages are prefixed differently — so they can be easily distinguished in the terminal — and our error message also includes the file name and line number (main.go:37) that called the logger?

Decoupled logging

A big benefit of logging your messages to the standard streams (stdout and stderr) like we are 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 streams are displayed in the terminal.

In staging or production environments, you can redirect the streams 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 stdout and stderr streams to on-disk files when starting the application like so:

$ go run ./cmd/web >>/tmp/info.log 2>>/tmp/error.log

The http.Server error log

There is one more change we need to make to our application. By default, if Go’s HTTP server encounters an error it will log it using the standard logger. For consistency it’d be better to use our new errorLog logger instead.

To make this happen we need to initialize a new http.Server struct containing the configuration settings for our server, instead of using the http.ListenAndServe() shortcut.

It’s probably easiest to demonstrate this:

File: cmd/web/main.go

package main

...

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

    flag.Parse()

    infoLog := log.New(os.Stdout, "INFO\t", log.Ldate|log.Ltime)
    errorLog := log.New(os.Stderr, "ERROR\t", log.Ldate|log.Ltime|log.Lshortfile)

    mux := http.NewServeMux()

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

    mux.HandleFunc("/", home)
    mux.HandleFunc("/snippet/view", snippetView)
    mux.HandleFunc("/snippet/create", snippetCreate)

    // Initialize a new http.Server struct. We set the Addr and Handler fields so
    // that the server uses the same network address and routes as before, and set
    // the ErrorLog field so that the server now uses the custom errorLog logger in
    // the event of any problems.
    srv := &http.Server{
        Addr:     *addr,
        ErrorLog: errorLog,
        Handler:  mux,
    }

    infoLog.Printf("Starting server on %s", *addr)
    // Call the ListenAndServe() method on our new http.Server struct.
    err := srv.ListenAndServe()
    errorLog.Fatal(err)
}

Additional information

Additional logging methods

So far in this book we’ve used the Println(), Printf() and Fatal() methods to write log messages, but Go provides a range of other methods that are worth familiarizing yourself with.

As a rule of thumb, you should avoid using the Panic() and Fatal() variations outside of your main() function — it’s good practice to return errors instead, and only panic or exit directly from main().

Concurrent logging

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

That said, if you have multiple 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.

Logging to a file

As I said above, my general recommendation is to log your output to standard streams and redirect the output to a file at runtime. But if you don’t want to do this, you can always open a file in Go and use it as your log destination. As a rough example:

f, err := os.OpenFile("/tmp/info.log", os.O_RDWR|os.O_CREATE, 0666)
if err != nil {
    log.Fatal(err)
}
defer f.Close()

infoLog := log.New(f, "INFO\t", log.Ldate|log.Ltime)