Video:

Logging with Logrus

February 28, 2021

Course Instructor: Elliot Forbes

Hey Gophers! My name is Elliot and I'm the creator of TutorialEdge and I've been working with Go systems for roughly 5 years now.

Our application is becoming more and more mature with every improvement we make. It’s now deployable to a K8s cluster, and it has some acceptance tests in place to ensure it behaves the way we expect when it goes live.

However, once our system does go live into production, we may have to start looking at the logs and understanding when particular things went wrong.

It is inevitable that some things will go wrong with our production applications. In order to help our future selves, we need to ensure that we’ve done what we can to make investigations as easy as possible. Having structured logging that can then be picked up by something like Datadog is vital in these investigations.

The Code

Let’s dive in and start in the main.go. Now originally, I had intended to use the App struct at the top to contain pointers to the database, but we ended up going down a cleaner path with the design. However, I do still want to put this to use and store some app specific stuff like the name of our Application:

package main

import (
	"fmt"
	"net/http"

	"github.com/TutorialEdge/go-rest-api-course/internal/comment"
	"github.com/TutorialEdge/go-rest-api-course/internal/database"
	transportHTTP "github.com/TutorialEdge/go-rest-api-course/internal/transport/http"

	log "github.com/sirupsen/logrus"
)

// App - the struct which contains information about our app
type App struct {
	Name    string
	Version string
}
...
func main() {
	app := App{
		Name:    "Comment API",
		Version: "1.0",
	}
	if err := app.Run(); err != nil {
		fmt.Println("Error starting up our REST API")
		fmt.Println(err)
	}
}

Next, I want to update what our application logs out upon startup, in the future, if you want to improve upon this and give yourself more clarity, then injecting the application version from your deployment pipeline as an environment variable can give you direct visibility into what is being deployed:

log.SetFormatter(&log.JSONFormatter{})
log.WithFields(
		log.Fields{
			"AppName":    app.Name,
			"AppVersion": app.Version,
		}).Info("Setting Up Our APP")

With this in place, we can then go through the rest of our main.go file and update every instance of fmt.Println to use the new log package:

package main

import (
	"net/http"

	"github.com/TutorialEdge/go-rest-api-course/internal/comment"
	"github.com/TutorialEdge/go-rest-api-course/internal/database"
	transportHTTP "github.com/TutorialEdge/go-rest-api-course/internal/transport/http"

	log "github.com/sirupsen/logrus"
)

// App - the struct which contains information about our app
type App struct {
	Name    string
	Version string
}

// Run - sets up our application
func (app *App) Run() error {
	log.SetFormatter(&log.JSONFormatter{})
	log.WithFields(
		log.Fields{
			"AppName":    app.Name,
			"AppVersion": app.Version,
		}).Info("Setting Up Our APP")

	var err error
	db, err := database.NewDatabase()
	if err != nil {
		return err
	}
	err = database.MigrateDB(db)
	if err != nil {
		log.Error("failed to setup database")
		return err
	}

	commentService := comment.NewService(db)
	handler := transportHTTP.NewHandler(commentService)
	handler.SetupRoutes()

	if err := http.ListenAndServe(":8080", handler.Router); err != nil {
		log.Error("Failed to set up server")
		return err
	}

	log.Info("App startup successful")
	return nil
}

func main() {
	app := App{
		Name:    "Comment API",
		Version: "1.0",
	}
	if err := app.Run(); err != nil {
		log.Error(err)
		log.Fatal("Error starting up our REST API")
	}
}

Awesome, now, if we try and run this locally with docker, we’ll notice there is one slight issue I forgot to address in the previous video. We need to make the database connection string backwards compatible so that we can disable ssl_mode when running within docker-compose. Let’s fix that now by adding to our deployment.yml:

- name: SSL_MODE
  value: "require"

And also updating our database package to get this from an environment variable:

sslmode := os.Getenv("SSL_MODE")

connectString := fmt.Sprintf("host=%s port=%s user=%s dbname=%s password=%s sslmode=%s", dbHost, dbPort, dbUsername, dbTable, dbPassword, sslmode)

Perfect, let’s now try and run our app using docker-compose:

$ docker-compose up --build

We should now see our App logs outputted like this:

comments-database | 
comments-database | PostgreSQL Database directory appears to contain a database; Skipping initialization
comments-database | 
comments-database | 2021-03-06 09:54:57.674 UTC [1] LOG:  starting PostgreSQL 12.2 on x86_64-pc-linux-musl, compiled by gcc (Alpine 9.2.0) 9.2.0, 64-bit
comments-database | 2021-03-06 09:54:57.674 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
comments-database | 2021-03-06 09:54:57.674 UTC [1] LOG:  listening on IPv6 address "::", port 5432
comments-database | 2021-03-06 09:54:57.677 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
comments-rest-api | {"AppName":"Comment API","AppVersion":"1.0","level":"info","msg":"Setting Up Our APP","time":"2021-03-06T09:54:58Z"}
comments-rest-api | {"level":"info","msg":"Setting up new database connection","time":"2021-03-06T09:54:58Z"}
comments-database | 2021-03-06 09:54:57.696 UTC [21] LOG:  database system was shut down at 2021-03-06 09:54:46 UTC
comments-database | 2021-03-06 09:54:57.701 UTC [1] LOG:  database system is ready to accept connections
comments-rest-api | Setting Up Routes

The logs from our main.go are now formatted and outputted in JSON and have a timestamp which is always incredibly handy when debugging! We now need to go through all of our code and update every call to fmt to use the logrus log package.

In the next video, we’ll look at how we can build middleware for our routes so that our app logs every request to an endpoint!