如何从中间件设置日志记录上下文？

Question

I want to populate the logging context by items in the request, for example: r.Header.Get("X-Request-Id"). I assumed I could override the Log type in the handler from middleware. Though it doesn't seem to work and I am not sure why!

package main

import (
    "fmt"
    "net/http"
    "os"

    "github.com/apex/log"
    "github.com/gorilla/mux"
)

// Assumption: handler is the shared state between the functions
type handler struct{ Log *log.Entry }

// New creates a handler for this application to co-ordinate shared resources
func New() (h handler) { return handler{Log: log.WithFields(log.Fields{"test": "FAIL"})} }

func (h handler) index(w http.ResponseWriter, r *http.Request) {
    h.Log.Info("Hello from the logger")
    fmt.Fprint(w, "YO")
}

func main() {
    h := New()

    app := mux.NewRouter()
    app.HandleFunc("/", h.index)
    app.Use(h.loggingMiddleware)

    if err := http.ListenAndServe(":"+os.Getenv("PORT"), app); err != nil {
        log.WithError(err).Fatal("error listening")
    }

}

func (h handler) loggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        h.Log = log.WithFields(log.Fields{"test": "PASS"})
        next.ServeHTTP(w, r)
    })
}

Can you see why h.Log = log.WithFields(log.Fields{"test": "PASS"}) doesn't seem to have any effect on h.Log.Info("Hello from the logger") which should be IIUC within the same request?

Answer 1

You need your logger to be request-scoped. You're setting it globally for the entire handler, every time a new connection comes in, which means you're asking for data races, and generally undesirable behavior.

For request-scoped context, the context.Context embedded in the request is perfect. You can access it through the Context() and WithContext methods.

Example:

var loggerKey = "Some unique key"

func (h handler) loggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        ctx := r.Context()
        ctx = context.WithValue(ctx, loggerKey, log.WithFields(log.Fields{"test": "PASS"}))
        next.ServeHTTP(w, r.WithContext(ctx)
    })
}

Then to access your logger:

func doSomething(r *http.Request) error {
    log, ok := r.Context().Value(loggerKey).(*log.Logger) // Or whatever type is appropriate
    if !ok {
        return errors.New("logger not set on context!")
    }
    // Do stuff...
}