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?

Do not change the signature of your HTTP handlers. It doesn't seem like a problem at first, but trust me, this will cause problems down the road. For instance, you cannot use your handlers in tests now without writing additional glue code. http.ResponseWriter is an interface. You can replace the standard implementation with [one that remembers the status code](https://upgear.io/blog/golang-tip-wrapping-http-response-writer-for-middleware/). Don't forget to implement the optional interfaces http.Flusher, http.Pusher, http.Hijacker, http.CloseNotifier, though. — Peter, Oct 07 '20 at 14:56

wijayaerick · Accepted Answer · 2020-10-07T18:19:58.930

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

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

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

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

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.

I tried what you wrote and like it. I'm using a websocket and with that it does not work well and results in: interface conversion: *apiserver.LogResponseWriter is not http.Hijacker: missing method Hijack. So my current hack is to check theif r.URL.Path == "/websocket" { handler.ServeHTTP(w, r) return } — qknight, Apr 06 '23 at 13:10
ahh it's because of the notorious optional interfaces (my answer did not cover them). See this blog for more details: https://blog.merovius.de/posts/2017-07-30-the-trouble-with-optional-interfaces/ — wijayaerick, Apr 12 '23 at 06:38

score 1 · Answer 2 · answered Apr 12 '23 at 10:41

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!

Go gorilla log each request duration and status code

2 Answers2