Discussion on: Contextual Logging In Go

[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.

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

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
}

[Clavin June]

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

[Clavin June]

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

[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.

[Clavin June]

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