Go gorilla log each request duration and status code

Question

I have a REST API written in Go1.13 using gorilla/mux v1.7.3 and gorilla/context v1.1.1.

I want to log each request duration and status code. I already have a basic working version, but I'm wondering if there is a cleaner option.

I have about 20 HTTP calls. Let's take one of them as an example:

client.HandleFunc("/register", register.Handle).Methods("POST") 

and the signature of register.Handle is:

func Handle(w http.ResponseWriter, r *http.Request) { ... }

So in order to log each request duration and status code, I simply wrapped the method handler register.Handle with a "log handler":

client.HandleFunc("/register", log.HandleRequestWithLog(register.Handle)).Methods("POST")

when log.HandleRequestWithLog simply times the function execution, and logs it with the returned status code (logging with Azure metrics):

func HandleRequestWithLog(h func(http.ResponseWriter, *http.Request) int) http.HandlerFunc {
    return func(writer http.ResponseWriter, request *http.Request) {
        startTime := time.Now()
        statusCode := h(writer, request)
        duration := time.Now().Sub(startTime)
        trace := appinsights.NewRequestTelemetry(request.Method, request.URL.Path, duration, string(rune(statusCode)))
        trace.Timestamp = time.Now()
        client.Track(trace)
    }
}

So in order to extract the status code, I needed every HTTP method to return the status code. So I changed the signature to:

func Handle(w http.ResponseWriter, r *http.Request) int { .. }

I was wondering if there is a better option than returning the HTTP status code for each request. Also, what will happen if I want more information from the request? I'll return this value as well?

Answer 1

Instead of changing HTTP handler signature, you can define a LogResponseWriter that implements http.ResponseWriter to keep track of response data (status, body, etc..).

1. Let's define LogResponseWriter

type LogResponseWriter struct {
    http.ResponseWriter
    statusCode int
    buf        bytes.Buffer
}

func NewLogResponseWriter(w http.ResponseWriter) *LogResponseWriter {
    return &LogResponseWriter{ResponseWriter: w}
}

func (w *LogResponseWriter) WriteHeader(code int) {
    w.statusCode = code
    w.ResponseWriter.WriteHeader(code)
}

func (w *LogResponseWriter) Write(body []byte) (int, error) {
    w.buf.Write(body)
    return w.ResponseWriter.Write(body)
}

2. Define LogMiddleware (here, I use std log and mux.MiddlewareFunc)

type LogMiddleware struct {
    logger *log.Logger
}

func NewLogMiddleware(logger *log.Logger) *LogMiddleware {
    return &LogMiddleware{logger: logger}
}

func (m *LogMiddleware) Func() mux.MiddlewareFunc {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
            startTime := time.Now()

            logRespWriter := NewLogResponseWriter(w)
            next.ServeHTTP(logRespWriter, r)

            m.logger.Printf(
                "duration=%s status=%d body=%s",
                time.Since(startTime).String(),
                logRespWriter.statusCode,
                logRespWriter.buf.String())
        })
    }
}

3. Start the server in main.go. Here, we can use the LogMiddleware in our router.

func main() {
    logger := log.New(os.Stdout, "", log.LstdFlags)

    router := mux.NewRouter()
    router.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        time.Sleep(1 * time.Second)

        w.WriteHeader(http.StatusOK)
        w.Header().Set("Content-Type", "application/json")
        w.Write([]byte(`{"msg": "hello world"}`))
    })

    logMiddleware := NewLogMiddleware(logger)
    router.Use(logMiddleware.Func())

    logger.Fatalln(http.ListenAndServe(":8080", router))
}

The log result when I visit http://localhost:8080:

2020/10/08 00:51:38 duration=1.003927394s status=200 body={"msg": "hello world"}

4. Follow up: What will happen if I want more information from the request?

In your log middleware, you can read the request header & body (from r *http.Request), then log them with the duration and response data. Note that you should reassign the request body so that your actual handlers can read the request body.

Answer 2

This is an answer to https://stackoverflow.com/a/64249969/1630083 (from below).

I had this issue with websockets I served:

http: panic serving 172.21.0.10:44614: interface conversion: *apiserver.LogResponseWriter is not http.Hijacker: missing method Hijack

But with the code from: http://www.inanzzz.com/index.php/post/q7bs/access-log-middleware-in-golang

// Overrides http.Flusher type.
func (w *LogResponseWriter) Flush() {
    if fl, ok := w.ResponseWriter.(http.Flusher); ok {
        if w.statusCode == 0 {
            w.WriteHeader(http.StatusOK)
        }
        fl.Flush()
    }
}

// Overrides http.Hijacker type.
func (w *LogResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
    hj, ok := w.ResponseWriter.(http.Hijacker)
    if !ok {
        return nil, nil, fmt.Errorf("the hijacker interface is not supported")
    }
    return hj.Hijack()
}

I got it working now, thanks!