restgologginggorilla

Go gorilla log each request duration and status code


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?


Solution

  • 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)
    }
    
    1. 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())
            })
        }
    }
    
    1. 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"}
    
    1. 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.