DEV Community

loading...

Contextual Logging In Go

Clavin June
a bunch of perceptrons
Originally published at clavinjune.dev on ・5 min read

Photo by @borisview on Unsplash

I’ve just woke up and somehow I remember 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.

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()
}
Enter fullscreen mode Exit fullscreen mode

Let’s test our base logger

func main() {
  configureBaseLogger()
  log.Info().Msg("testing")
}
Enter fullscreen mode Exit fullscreen mode

Output:

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

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.

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")
  }
}
Enter fullscreen mode Exit fullscreen mode

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.

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
}
Enter fullscreen mode Exit fullscreen mode

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.

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())
  }
}

Enter fullscreen mode Exit fullscreen mode

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

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
Enter fullscreen mode Exit fullscreen mode

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

$ 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
Enter fullscreen mode Exit fullscreen mode

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.

Discussion (6)

Collapse
feketegy profile image
George

If I understand correctly...

All your functions would need the context passed into it in this case and any 3rd party module functions that you're using would need to be decorated so you can pass in the context if the function doesn't accept one.

This would be a horrible pattern to follow.

A better solution would be to just embed errors in each other, then "unwrap" those errors in a middleware after you execute the http handler logic, but before you're returning the http response.

If an error happened downstream you can log it in the middleware and return the appropriate response.

Embedding errors is necessary so you know the execution path and the stack trace which you should log. Attaching function names, function arguments and any other environment variables to the error you're returning as meta data is also very good practice to follow.

An example execution path would be Func1 -> Func2 -> Func3 and Func3 returns an error so Func3 embeds the original error and return -> Func2 embedes Func3 error and return -> Func1 embeds Func2 error and return to the original caller which might be the http handler.

The middleware picks it up, unwraps the embedded errors and logs it with the full stack trace and you'll know exactly which function triggered the error and through which other functions it traversed.

Collapse
kunde21 profile image
Chad Kunde

The http Request contains its respective context at r.Context() and can be assigned a new context using r = r.WithContext(ctx).

Go rewards the concept of handling the error as close to the source as possible, so adding contextual data to the logger makes more sense. By logging the error where it's generated, there's no reason to thread that same error value up through the call stack.

This isn't necessarily production-ready (as admitted by the author) because there's no protection on the context. By moving the loading and extracting to a separate package, the type restrictions benefit you:

package myctxlog
type logKey struct{}
func WithLogger(ctx context.Context, logger zerolog.Logger) context.Context {
    return context.WithValue(ctx, logKey{}, logger)
}

func FromContext(ctx context.Context) zerolog.Logger {
    l := ctx.Value(logKey{})
    if l == nil {
        return <default value>
    }
    return l.(zerolog.Logger)
}
Enter fullscreen mode Exit fullscreen mode

By doing so, the type checking will ensure that only a zerolog.Logger is allowed to be loaded into the context. Your risk of error is eliminated. Now, the resulting handler looks like:

package main

import (
  "context"
  "fmt"
  "net/http"
  "os"
  "strings"
  "time"

  "github.com/google/uuid"
  "github.com/rs/zerolog"
  "github.com/rs/zerolog/log"
  "github.com/<mypackage>/ctxlog"
)

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

  // NOTE:  configured logger can be injected in the middleware instead of using a global variable.
  http.Handle("/", middleware(handler))

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

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()
}

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

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")

    statusCode := next(writer, request.WithContext(
        ctxlog.WithLogger(r.Context(), subLogger)
    )
    // NOTE:  status code is set to 200 when the first write is initiated.
    writer.WriteHeader(statusCode)

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

func anotherFunc(ctx context.Context) {
  logger := ctxlog.FromContext(ctx)
  // USE:  Error can be logged with all context at the point of error generation.  No need to thread it back up the call stack unless other error handling is involved.
  logger.Info().Msg("inside anotherFunc")
}

func handler (writer http.ResponseWriter, request *http.Request) int {
  logger := ctxlog.FromContext(ctx)
  logger.Info().Msg("inside handler")

  anotherFunc(request.Context())

  return 204
}
Enter fullscreen mode Exit fullscreen mode
Collapse
clavinjune profile image
Clavin June Author

@kunde21 Yes, of course, using iota is not a good one to put value with, using a predefined struct would works!

Collapse
clavinjune profile image
Clavin June Author • Edited

hi @feketegy , I believe that would be awesome if all the functions you mentioned are return error, but it'll be hard if the functions return something else other than error. But it is possible to decorate all the function to collect the error, I've tried another method to trace the error stack using panic but not recommended

But I also believe decorating handler with middleware is not a horrible pattern since google put context as the first argument in their functions

Collapse
feketegy profile image
George

Yes, this strategy doesn't work if you care and want to log more things other than errors. In my mind if a program doesn't work correctly it should return an error to have the opportunity to resolve the error or re-try running the code again or bubbling the error all the way up on the call stack to log it.

Still, if you want to log information other than errors it should be done separately from error handling, to rephrase that, it shouldn't be mixed with error handling.

Thread Thread
clavinjune profile image
Clavin June Author

Yes that could be better if golang support AOP, we can eliminate logging / error handling aspect away from business & system logic