Transaction ID Logging in Go

Introduction

I recently had a requirement to include a transaction id with every log statement executed as part of an HTTP request. How would one do that without explicitly passing a transaction id into every call invoked as part of the request? This article will show you one approach. And of course, if there is a better way to approach this, hopefully Cunningham's Law will kick in and I'll learn something new.

Here is the code: https://github.com/wkrause13/go-transactionid-tutorial

Edit: Some comments on Reddit with alternative approaches: https://www.reddit.com/r/golang/comments/t4pjuv/transaction_id_logging_in_go/

I'll also quickly comment on why you might want to do this at all. In a perfect world, you wouldn't need to pass a transaction ID deep into the bowels of your code. Errors would bubble up in a transparent way. However, if you're inheriting a large code base that is not well structured, with a lot of global state and inconsistent error handling, then this approach is a pragmatic way to see what is going on using a tool like Kibana.

tl;dr

Use middleware to generate an id and pass it through context to your handler. Use the repository pattern to encapsulate your business logic. Clone your repo, passing in a new sub logger that includes the transaction id as a structured field.

Before we begin, I assume that you are familiar with the repository pattern. If not, I encourage you to read more about it. If you’ve ever worked on a project that relied exclusively on integration tests (I’m looking at you docker-compose.yaml), it’s probably because the project didn’t take care to encapsulate code that interacts with external services.

I try to keep this as self-contained as possible, so some elements of the sample code will be contrived by design. Use your judgement when adapting this code to any production use case.

Middleware

Let's start with our middleware:

package middleware

import (
	"context"
	"math/rand"
	"net/http"
	"time"
)

type key int

const (
	TransactionId key = iota
)

func TransactionIdMiddleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		//would use a uuid in prod, want to keep things simple here
		s1 := rand.NewSource(time.Now().UnixNano())
		r1 := rand.New(s1)
		ctx := context.WithValue(r.Context(), TransactionId, r1.Intn(1000000000))

		next.ServeHTTP(w, r.WithContext(ctx))
	})
}

All we do in this middleware function is generate a transaction id and add it to context. I'm using a typed key to keep the staticcheck linter happy.

Repositories

Let's move on to our repository. This repo is a generic stand in for any external service your code might interface with, for example a database. By defining an interface GenericDataRepo, we allow our actual implementation of DataRepo to be mocked.

type GenericDataRepo interface {
	CloneWithTransID(transID int) GenericDataRepo
	ListUsers() []string
}

Now we need to define a struct type that conforms to this interface

type DataRepo struct {
	logger *zap.Logger
	db     *FakeDB
}

As you might imagine, the CloneWithTransID will take an existing DataRepo and return a copy with a modified logger field which includes the transaction ID. Pointers are convenient here, as this clone function will be invoked on every HTTP call, so we want to avoid unnecessarily allocating memory through a proper clone.

func (d DataRepo) CloneWithTransID(transID int) GenericDataRepo {
	newLogger := d.logger.With(zap.Int("transID", transID))
	return DataRepo{logger: newLogger, db: d.db}
}

Finally, we define our ListerUsers function

func (d DataRepo) ListUsers() []string {
	d.logger.Info("getting users")
	return d.db.GetUsers()
}

Like in this example, you would use d.logger for all logging within this repo. By making the logger a field on DataRepo, you avoid having to pass around a transaction id explicitly to your functions.

The full repo file looks like this:

package repositories

import "go.uber.org/zap"

type GenericDataRepo interface {
	CloneWithTransID(transID int) GenericDataRepo
	ListUsers() []string
}

type DataRepo struct {
	logger *zap.Logger
	db     *FakeDB
}

func NewDataRepo() DataRepo {
	db := connectToDb()
	logger, _ := zap.NewProduction()
	return DataRepo{logger: logger, db: &db}
}

func (d DataRepo) CloneWithTransID(transID int) GenericDataRepo {
	newLogger := d.logger.With(zap.Int("transID", transID))
	return DataRepo{logger: newLogger, db: d.db}
}

func (d DataRepo) ListUsers() []string {
	d.logger.Info("getting users")
	return d.db.GetUsers()
}

type FakeDB struct{}

func (m FakeDB) GetUsers() []string {
	return []string{"amy", "bob", "carl"}
}

func connectToDb() FakeDB {
	return FakeDB{}
}

Handlers

Our handler is pretty simple:

func (h HelloWorldHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
	transID := r.Context().Value(middleware.TransactionId).(int)
	repo := h.dataRepo.CloneWithTransID(transID)
	users := repo.ListUsers()
	fmt.Fprintf(w, "Hello World: "+users[0])
}

All we do is grab the id from context, clone our repo and then use that cloned repo to execute the business this route is responsible for.

Main

Bringing it all together, our main.go file now looks like this:

package main

import (
	"net/http"

	"github.com/go-chi/chi"

	"github.com/wkrause13/go-transactionid-tutorial/handlers"
	"github.com/wkrause13/go-transactionid-tutorial/middleware"
	"github.com/wkrause13/go-transactionid-tutorial/repositories"
)

const (
	GET = "GET"
)

func main() {
	r := chi.NewRouter()
	r.Use(middleware.TransactionIdMiddleware)
	dataRepo := repositories.NewDataRepo()

	handler := handlers.NewHelloWorldHandler(dataRepo)

	r.Method(GET, "/", handler)
	http.ListenAndServe(":3000", r)
}

If you start this server and go to http://localhost:3000/, you will see in the terminal that a transaction ID is included in your log statement.

Conclusion

So there you have it, a way to bring the print line debugging to Kibana. If you are in complete control of your codebase, then it may not make sense to carry a transaction id deep into your code. However, if you're working on something that can't be completely rewritten, wrapping what is already there in this repo pattern is one way to gain some visibility into the paths a given request is exercising.