Simple HTTP request logging middleware in Go

When we’re building a web application there’s some shared functionality that we want to run for many (or even all) HTTP requests. We might want to log every request, gzip every response, or authenticate request before doing any processing. There are already libraries present which do this, but its always fun learning something new and building on your own.

In this post I’m going to explain how to make a simple custom request logging middleware which can be used with gorilla/mux. Our middleware will log each incoming request to the application and will log the following parameters:

1. Request Method
2. Request Host
3. Request Path
4. Request query parameters
5. Time took to complete request
6. Response status code

Given below is a simple Go program which has 2 APIs, /ping, /hello.

package main

import (
	"net/http"

	"github.com/gorilla/mux"
)

func main() {
	r := mux.NewRouter()
	r.HandleFunc("/ping", handlePing).Methods(http.MethodGet)
	r.HandleFunc("/hello", handleHello).Methods(http.MethodGet)
	http.ListenAndServe(":http", r)
}

func handlePing(rw http.ResponseWriter, req *http.Request) {
	rw.Write([]byte("I am working...\n"))
	return
}

func handleHello(rw http.ResponseWriter, req *http.Request) {
	rw.Write([]byte("Hi, how are you...\n"))
	return
}

Writing the middleware

Now we will write a simple middleware, which logs all the incoming requests to our application. Initially we will only focus on printing the first 4 parameters.

func RequestLoggerMiddleware(r *mux.Router) mux.MiddlewareFunc {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
            defer func() {
                log.Printf(
                    "[%s] %s %s %s",
                    req.Method,
                    req.Host,
                    req.URL.Path,
                    req.URL.RawQuery,
                )
            }()

            next.ServeHTTP(w, req)
        })
    }
}

We can use this with mux router as below:

r.Use(RequestLoggerMiddleware(r))

So the complete main function looks like

func main() {
    r := mux.NewRouter()
    r.HandleFunc("/ping", handlePing).Methods(http.MethodGet)
    r.HandleFunc("/hello", handleHello).Methods(http.MethodGet)
    r.Use(RequestLoggerMiddleware(r))
    http.ListenAndServe(":http", r)
}

Lets try calling the APIs now and check how the requests are being logged now:

Perfect, this looks great! Now we also want to add the time taken by the API. This can be done very easily in the middleware function by adding the following:

func RequestLoggerMiddleware(r *mux.Router) mux.MiddlewareFunc {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
            start := time.Now()
            defer func() {
                log.Printf(
                    "[%s] [%v] %s %s %s",
                    req.Method,
                    time.Since(start),
                    req.Host,
                    req.URL.Path,
                    req.URL.RawQuery,
                )
            }()

            next.ServeHTTP(w, req)
        })
    }
}

So now the new output is something like below

Looks better! So the only part remaining is to add the response status code in the log message.

Do we have access to response status code in middleware ? Does http.ResponseWriter help ?

Frankly speaking, there is no direct way of adding that. In Go APIs, we use the response writer http.ResponseWriter object to write status codes in APIs. If we closely look at the implementation of http.ResponseWriter , it is an interface and has the following methods:

type ResponseWriter interface {
    Header() Header
    Write([]byte) (int, error)
    WriteHeader(statusCode int)
}

From our API methods, we call WriteHeader method on response writer object.

func handleHello(rw http.ResponseWriter, req *http.Request) {
    rw.WriteHeader(http.StatusOK)
    rw.Write([]byte("Hi, how are you...\n"))
    return
}

Though in our middleware we don’t have access to this status code and thus we cannot print it. To solve this problem, we will use a very cool feature of Golang and will embed the ResponseWriter interface in a custom struct. This custom struct will have a statusCode field inside it and thus can be used to print the status code in request logs. Let’s see how:

type statusResponseWriter struct {
    http.ResponseWriter
    statusCode int
}

// NewStatusResponseWriter returns pointer to a new statusResponseWriter object
func NewStatusResponseWriter(w http.ResponseWriter) *statusResponseWriter {
    return &statusResponseWriter{
        ResponseWriter: w,
        statusCode:     http.StatusOK,
    }
}

So we created a new structure statusResponseWriter which contains the statusCode field in it. Now since this structure embeds http.ResponseWriter interface, its methods are seen as if the custom struct is also implementing them.

When interfaces are embedded, their methods are promoted automatically. That means methods of interface are seen as if they are methods of the embedding struct

This means an object of our custom struct can be passed to ServeHTTP function, since it implements the http.ResponseWriter interface. But here comes another cool feature, we can also override the methods of interface.

It’s here where we do all the magic to assign the statusCode field of our custom struct whenever there is a WriteHeader from the API.

// WriteHeader assigns status code and header to ResponseWriter of statusResponseWriter object
func (sw *statusResponseWriter) WriteHeader(statusCode int) {
    sw.statusCode = statusCode
    sw.ResponseWriter.WriteHeader(statusCode)
}

Now let’s see how we can use the custom struct statusResponseWriter to print the status code in request logs. So instead of passing w http.ResponseWriter to ServeHTTP method, we pass sw statusResponseWriter to it. Then we use sw.statusCode field to log the response status code and thats it the work is done here!

func RequestLoggerMiddleware(r *mux.Router) mux.MiddlewareFunc {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
			start := time.Now()
			sw := NewStatusResponseWriter(w)

			defer func() {
				log.Printf(
					"[%s] [%v] [%d] %s %s %s",
					req.Method,
					time.Since(start),
					sw.statusCode,
					req.Host,
					req.URL.Path,
					req.URL.RawQuery,
				)
			}()

			next.ServeHTTP(sw, req)
		})
	}
}

Let’s see how the final logs look now:

Wow! Amazing, our custom logging middleware is complete now and looks good! Try playing around with it and you can print all cool things like user agent, host ip etc in the request logs according to your use case.

Please comment and share if you liked this post. If you have any suggestions or feedback, please comment, we will be happy to discuss and improve this post. Thanks a lot for reading!