Contextual Logging in Go

tech · Dec 19, 2020 · ~5 min
Photo by @borisview on Unsplash
Photo by @borisview on Unsplash

I’ve just woke up and somehow I remembered when I created taboo to trace the error log. And then I think, would it be better if I pass the logger instead of the error log itself?

As the context passed, it will contain a sub-logger that has x-request-id inside it. It’ll trace all the requested event from HTTP Handler to the most corner of the function.

I don’t know if this gonna be good because I wrote this immediately right after I woke up. This might be not optimized or perhaps an anti-pattern. But at least this could be a reference for you to create a contextual logger.

Logger

First thing first, you need a logger. Might be anything, but I will use zerolog in this post. I won’t explain about zerolog since you can use anything you want.

Format the base logger to match your logging style.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15

func configureBaseLogger() {
  output := zerolog.ConsoleWriter{
    Out: os.Stdout,
    FormatTimestamp: func(i interface{}) string {
      parse, _ := time.Parse(time.RFC3339, i.(string))
      return parse.Format("2006-01-02 15:04:05")
    },
    FormatLevel: func(i interface{}) string {
      return strings.ToUpper(fmt.Sprintf(" %-6s ", i))
    },
  }

  log.Logger = zerolog.New(output).With().
    Timestamp().CallerWithSkipFrameCount(2).Logger()
}

Let’s test our base logger

1
2
3
4

func main() {
  configureBaseLogger()
  log.Info().Msg("testing")
}

Output:

1

2020-12-19 01:01:37  INFO    logger/main.go:57 > testing

LGTM! Let’s continue creating our handler!

Middleware

Here I’ll log the request using the middleware. So I’m gonna make a new type of handler to matched my middleware.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27

type HandlerFuncWithStatus func(writer http.ResponseWriter, request *http.Request) int

const (
  LoggerCtxKey = iota
)

func middleware(next HandlerFuncWithStatus) http.HandlerFunc {
  return func(writer http.ResponseWriter, request *http.Request) {
    requestId := request.Header.Get("x-request-id")

    if requestId == "" {
      requestId = uuid.New().String()
    }

    subLogger := log.With().Str("requestId", requestId).Logger()

    subLogger.Info().
      Str("path", request.URL.Path).
      Str("method", request.Method).Msg("in")

    ctx := context.WithValue(context.Background(), LoggerCtxKey, subLogger)
    statusCode := next(writer, request.WithContext(ctx))
    writer.WriteHeader(statusCode)

    subLogger.Info().Int("status", statusCode).Msg("out")
  }
}

The main idea is:

  1. Get x-request-id if exists, otherwise create one with UUIDv4 format
  2. Create a sub-logger from our base-logger and then initiate it with the request id
  3. Log the method and path, you can do anything in this step tho
  4. Put the logger into the context and pass it to the http handler
  5. Finally set and log the http status code

HTTP Handler

Now we’re gonna create the http handler that will use our middleware. It doesn’t need to be fancy.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13

func anotherFunc(ctx context.Context) {
  logger := ctx.Value(LoggerCtxKey).(zerolog.Logger)
  logger.Info().Msg("inside anotherFunc")
}

func handler (writer http.ResponseWriter, request *http.Request) int {
  logger := request.Context().Value(LoggerCtxKey).(zerolog.Logger)
  logger.Info().Msg("inside handler")
  
  anotherFunc(request.Context())

  return 204
}

So now all the function that has the context passed from the middleware can access the logger by the context key.

Let’s assemble all the codes.

Final

This will be the final look of our code.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82

package main

import (
  "context"
  "fmt"
  "github.com/google/uuid"
  "github.com/rs/zerolog"
  "github.com/rs/zerolog/log"
  "net/http"
  "os"
  "strings"
  "time"
)

type HandlerFuncWithStatus func(writer http.ResponseWriter, request *http.Request) int

const (
  LoggerCtxKey = iota
)

func middleware(next HandlerFuncWithStatus) http.HandlerFunc {
  return func(writer http.ResponseWriter, request *http.Request) {
    requestId := request.Header.Get("x-request-id")

    if requestId == "" {
      requestId = uuid.New().String()
    }

    subLogger := log.With().Str("requestId", requestId).Logger()

    subLogger.Info().
      Str("path", request.URL.Path).
      Str("method", request.Method).Msg("in")

    ctx := context.WithValue(context.Background(), LoggerCtxKey, subLogger)
    statusCode := next(writer, request.WithContext(ctx))
    writer.WriteHeader(statusCode)

    subLogger.Info().Int("status", statusCode).Msg("out")
  }
}

func anotherFunc(ctx context.Context) {
  logger := ctx.Value(LoggerCtxKey).(zerolog.Logger)
  logger.Info().Msg("inside anotherFunc")
}

func handler (writer http.ResponseWriter, request *http.Request) int {
  logger := request.Context().Value(LoggerCtxKey).(zerolog.Logger)
  logger.Info().Msg("inside handler")

  anotherFunc(request.Context())

  return 204
}

func configureBaseLogger() {
  output := zerolog.ConsoleWriter{
    Out: os.Stdout,
    FormatTimestamp: func(i interface{}) string {
      parse, _ := time.Parse(time.RFC3339, i.(string))
      return parse.Format("2006-01-02 15:04:05")
    },
    FormatLevel: func(i interface{}) string {
      return strings.ToUpper(fmt.Sprintf(" %-6s ", i))
    },
  }

  log.Logger = zerolog.New(output).With().
    Timestamp().CallerWithSkipFrameCount(2).Logger()
}

func main() {
  configureBaseLogger()
  log.Info().Msg("testing")

  http.Handle("/", middleware(handler))

  if err := http.ListenAndServe(":8000", nil) ; err != nil {
    log.Error().Msg(err.Error())
  }
}

Try it by accessing http://localhost:8000. The output looks like this if I accessed it twice.

1
2
3
4
5
6
7
8
9

2020-12-19 01:25:16  INFO    logger/main.go:75 > testing
2020-12-19 01:25:20  INFO    logger/main.go:33 > in method=GET path=/ requestId=6eb1f209-dac9-42b2-8ba4-883efffcbd9e
2020-12-19 01:25:20  INFO    logger/main.go:50 > inside handler requestId=6eb1f209-dac9-42b2-8ba4-883efffcbd9e
2020-12-19 01:25:20  INFO    logger/main.go:45 > inside anotherFunc requestId=6eb1f209-dac9-42b2-8ba4-883efffcbd9e
2020-12-19 01:25:20  INFO    logger/main.go:39 > out requestId=6eb1f209-dac9-42b2-8ba4-883efffcbd9e status=204
2020-12-19 01:25:31  INFO    logger/main.go:33 > in method=GET path=/ requestId=88a140b8-2aed-4d82-bf56-0ab9a1c7cce0
2020-12-19 01:25:31  INFO    logger/main.go:50 > inside handler requestId=88a140b8-2aed-4d82-bf56-0ab9a1c7cce0
2020-12-19 01:25:31  INFO    logger/main.go:45 > inside anotherFunc requestId=88a140b8-2aed-4d82-bf56-0ab9a1c7cce0
2020-12-19 01:25:31  INFO    logger/main.go:39 > out requestId=88a140b8-2aed-4d82-bf56-0ab9a1c7cce0 status=204

Now if you want to trace all the event you can log it to the file and grep the request id.

1
2
3
4
5

$ grep 88a140b8-2aed-4d82-bf56-0ab9a1c7cce0 /tmp/log
2020-12-19 01:25:31  INFO    logger/main.go:33 > in method=GET path=/ requestId=88a140b8-2aed-4d82-bf56-0ab9a1c7cce0
2020-12-19 01:25:31  INFO    logger/main.go:50 > inside handler requestId=88a140b8-2aed-4d82-bf56-0ab9a1c7cce0
2020-12-19 01:25:31  INFO    logger/main.go:45 > inside anotherFunc requestId=88a140b8-2aed-4d82-bf56-0ab9a1c7cce0
2020-12-19 01:25:31  INFO    logger/main.go:39 > out requestId=88a140b8-2aed-4d82-bf56-0ab9a1c7cce0 status=204

That should be enough for the reference. Please modify the code according to your usage. I didn’t test for the performance nor benchmarking it so take it with a grain of salt.

Thank you for reading!

· · ·

Love This Content?

Any kind of supports is greatly appreciated! Kindly support me via Bitcoin, Ko-fi, Trakteer, or just continue to read another content. You can write a response via Webmention and let me know the URL via Telegraph.