How To Use Structured JSON Logging in Golang Applications

Structured logs are important for software debugging. Gladly, it is super easy to implement in Golang

by Percy Bolmér, August 9, 2021

Sick and tired of going through unstructured logs to track down a bug? Ever tried forcing a team of developers to write down their error messages in a structured way?

Well, you’ve come to the right place in your journey to stop bad software logs.

What Is Structured Logging?

Logging is a very important part of software. We do need logs to keep track of what’s going on in systems and as they grow large it becomes increasingly important.

There are many great tools out there that help us parse logs. I’m personally a great fan of ElasticSearch for instance. But these tools are most of the time depending on a structured log, not a plain text blob mass that may or may not be written in a certain format.

I remember when being assigned a bug to track down, the system had about 30 CRON jobs running some scripts, and all the scripts wrote their output to a single file which was rotated by date. So there was at least some kind of central logging (not the most recommended one, but hey). There were logs for this ancient system, so I went in, duct tape in hand; I was going to patch this bug.

The first thing I met in the logs was horrible: every script printed simple text messages to the log file with no information at all about what service it was. There was no context, no information to reproduce the bugs, nothing. I stared with big watery eyes at this:

"" not allowed

Logs were filling up fast, and the old log files were massive. Not strange since there were about 50–60 bash scripts which were all pretty big and running frequently. It took me quite a while to actually track down the bug, time that could have easily been saved with structured logs.

Structured logs are logs written in a well-known format to help read / query and store them. One of the most common ways is JSON formatted logs.

In these logs, you can specify a few fields that have to be available that will always help to debug. Let’s imagine that this horror system of mine used structured logging. If it did, the output would be something like the following:

{ "date": "2001-02-03", "service": "buggy-script", "level": "Warning", "message": "'' not allowed", "context": "validateInputFunction"}

Effortless Structured Logs in Golang

Structured logs are easy in Golang, so if you’re not already using them, you should start. There are a few packages out there that do help. The one I tend to use is a library called rs/zerolog. There are a few other competitors for the best log package out there, including the following:

• rs/zerolog — Blazing fast JSON structured logs, my main go-to logging package

• sirupsen/logrus — Probably the most popular logging package out there, structured JSON logs.

• uber-go/zap — Super speedy logger using structured JSON logs.

• natefinch/lumberjack — Log rotation package, mostly used with file-based logs in my experience.

I won’t compare the packages in this article, but maybe in the future. Let’s begin by using zerolog to try out how we can use it super easily and with some nice-to-know features.

We will begin by comparing the regular log package output just to show you what a structured log looks like. This also shows you that zerolog is compatible with the regular logger, so you could just replace the import package. But that won’t give you all the nice features that we will use soon. Here’s the code sample

package main

import (
	"log"
	zlog "github.com/rs/zerolog/log"
)

func main() {
	log.Print("Hello")
	zlog.Print("Hello")
}

2021/08/04 21:19:40 Hello
{"level":"debug", "time":"2021-08-04T21:19:40+02:00","message":"Hello"}

But what if we want to add more JSON fields? That is easy enough using the chainable API of zerolog. Most of the functions return a zerolog. The event, which allows us to call the functions recursively.

Let’s add a field for the service name and some data about what went wrong. Depending on the data type, you should use the appropriate function. You can find all available fields here.

package main

import (
	"github.com/rs/zerolog/log"
)

func main() {

	// Log with service name
	log.Info().
		Str("service", "my-service").
		Int("Some integer", 10).
		Msg("Hello")
}

{"level":"info","service":"my-service","Some integer":10,"time":"2021-08-04T21:30:56+02:00","message":"Hello"}

See the Info() function? This is used to control what log level to use. Yes, it does have Log levels. Another extra layer to control the logs is great. For instance, I often use a DEBUG flag for my programs, and switching that on has a lot of logs outputted that are not logged in production.

This is easy to accomplish with log levels. Let’s try it out with a simple program — try switching the debug flag and controlling the output. Here’s the code:

package main

import (
	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
)

func main() {

	// Apply zerolog global level, this will stop zerolog from logging any debug messages
	debug := false
	// Apply log level in the beginning of the application
	zerolog.SetGlobalLevel(zerolog.InfoLevel)
	if debug {
		zerolog.SetGlobalLevel(zerolog.DebugLevel)
	}
	// Log with service name
	log.Info().
		Str("service", "my-service").
		Int("Some integer", 10).
		Msg("Hello")
	// Debug log
	log.Debug().Msg("Exiting Program")
}

{"level":"info","service":"my-service","Some integer":10,"time":"2021-08-04T21:37:09+02:00","message":"Hello"}

Remember that each log level has a value, and if you have a log level with a value that is too high you won’t see all logs. So, use it with care. For instance, if we set the global log level to “Fatal,” we won’t even see the info log. You can view all log levels and the hierarchy in the zerolog documentations.

What About Don’t Repeat Yourself (DRY)?

Right now you’re probably thinking, “Great, logs look great.” But that is a lot of typing for a simple log, and I need to repeat the service name over and over.

Gladly, zerolog allows us to create custom loggers with default values.

Let’s create a program that says Hello and logs each time with a counter that is included in each log message. This time, let’s add the default fields when we create the logger. Again, we can use all the data types mentioned in the documentation. Here’s the code:

package main

import (
	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
)

var (
	HelloCounter = 1
	logger       zerolog.Logger
)

func main() {
	// Build a logger with default fields
	logger = log.With().
		Str("service", "my-service").
		Str("node", "localhost").
		Logger()

	Hello()
	Hello()
}
func Hello() {
	// Log with service name
	logger.Info().
		Int("count", HelloCounter).
		Msg("Hello")
	HelloCounter++
}

{"level":"info","service":"my-service","node":"localhost","count":1,"time":"2021-08-04T21:47:34+02:00","message":"Hello"}
{"level":"info","service":"my-service","node":"localhost","count":2,"time":"2021-08-04T21:47:34+02:00","message":"Hello"}

Conclusion

Hopefully, you find Zerolog easy to use. It has helped me a lot during my development. I won’t be going into how to ingest these logs from Stdout into popular frameworks such as Elasticsearch in this post.

But stay tuned, as I am always happy to hear from readers with feedback or questions.

That’s all for this time. Get out there and log everything in the world!