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()
}
Let’s test our base logger
func main() {
configureBaseLogger()
log.Info().Msg("testing")
}
Output:
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.
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:
- Get
x-request-idif exists, otherwise create one with UUIDv4 format - Create a sub-logger from our base-logger and then initiate it with the
request id - Log the method and path, you can do anything in this step tho
- Put the logger into the context and pass it to the http handler
- 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
}
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())
}
}
Try it by accessing https://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
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
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.
Top comments (6)
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.
The http Request contains its respective context at
r.Context()and can be assigned a new context usingr = 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:
By doing so, the type checking will ensure that only a
zerolog.Loggeris allowed to be loaded into the context. Your risk of error is eliminated. Now, the resulting handler looks like:@kunde21 Yes, of course, using iota is not a good one to put value with, using a predefined struct would works!
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
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.
Yes that could be better if golang support AOP, we can eliminate logging / error handling aspect away from business & system logic