Simple GoLang HTTP Logging Middleware

GoLang’s net/http package provides client and server implementation for HTTP. For applications where there is less logic involved with the request and response objects, we could directly use net/http instead of any web frameworks as the abstractions provided by a framework is unnecessary in such cases. One example I could think of is prometheus-exporters. Usually, it will have a /metrics endpoint that returns metrics for a component as plain text.

The server provided by net/http does not log request/response by default. A feedback containing URI, method, status code, duration, etc. would be really helpful. I was using logrus for logging in my application. So my use case was to log the request/response details using logrus.

For demonstration lets create an app that has a /ping endpoint that returns "pong".

func main() {
    http.Handle("/ping", pingHandler())

    addr := "127.0.0.1:8080"
    logrus.WithField("addr", addr).Info("starting server")
    if err := http.ListenAndServe("127.0.0.1:8080", nil); err != nil {
        logrus.WithField("event", "start server").Fatal(err)
    }
}

func pingHandler() http.Handler {
    fn := func(rw http.ResponseWriter, r *http.Request) {
        rw.WriteHeader(http.StatusOK)
        _, _ = fmt.Fprintf(rw, "pong")
    }
    return http.HandlerFunc(fn)
}

If we run the app and hit /ping we will get a response "pong".

$ curl --include localhost:8080/ping
HTTP/1.1 200 OK
Date: Mon, 10 Aug 2020 19:21:25 GMT
Content-Length: 7
Content-Type: text/plain; charset=utf-8

healthy

However, there won’t be any feedback to stdout from the app.

$ go run main.go
INFO[0000] starting server    addr="127.0.0.1:8080"

Log Request Details

First lets log the request details like URI, method and time taken to complete the request. To do that, write a wrapper function called WithLogging that wraps a given http.Handler, adds additional code to log the request details and returns a new http.Handler.

func WithLogging(h http.Handler) http.Handler {
    logFn := func(rw http.ResponseWriter, r *http.Request) {
        start := time.Now()

        uri := r.RequestURI
        method := r.Method
        h.ServeHTTP(rw, r) // serve the original request

        duration := time.Since(start)

        // log request details
        log.WithFields(log.Fields{
            "uri":      uri,
            "method":   method,
            "duration": duration,
        })
    }
    return http.HandlerFunc(logFn)
}

Wrap the pingHandler() with WithLogging() like this:

http.Handle("/ping", WithLogging(pingHandler()))

Now if we run and hit /ping request details will be logged to stdout:

$ go run main.go
INFO[0000] starting server    addr="127.0.0.1:8080"
INFO[0001] request completed    duration="9.123µs" method=GET uri=/ping

Log Response Details

Now, let’s add response details like status code and content size to the log. This part will be a bit tricky because we need to get those details somehow after our handler’s ServeHTTP(rw http.ResponseWriter, r *http.Request) was called. The first argument rw http.ResponseWriter is responsible for writing the response content like body and status code. It implements the interface http.ResponseWriter shown below:

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

The idea is to inject our own implementation of http.ResponseWriter that overrides,

• Write() method for capturing the size
• WriteHeader() method for capturing the status code.

type (
    // struct for holding response details
    responseData struct {
        status int
        size   int
    }

    // our http.ResponseWriter implementation
    loggingResponseWriter struct {
        http.ResponseWriter // compose original http.ResponseWriter
        responseData *responseData
    }
)

func (r *loggingResponseWriter) Write(b []byte) (int, error) {
    size, err := r.ResponseWriter.Write(b) // write response using original http.ResponseWriter
    r.responseData.size += size // capture size
    return size, err
}

func (r *loggingResponseWriter) WriteHeader(statusCode int) {
    r.ResponseWriter.WriteHeader(statusCode) // write status code using original http.ResponseWriter
    r.responseData.status = statusCode // capture status code
}

Updated WithLogging() function using loggingResponseWriter:

func WithLogging(h http.Handler) http.Handler {
    loggingFn := func(rw http.ResponseWriter, req *http.Request) {
        start := time.Now()

        responseData := &responseData{
            status: 0,
            size:   0,
        }
        lrw := loggingResponseWriter{
            ResponseWriter: rw, // compose original http.ResponseWriter
            responseData: responseData,
        }
        h.ServeHTTP(&lrw, req) // inject our implementation of http.ResponseWriter

        duration := time.Since(start)

        logrus.WithFields(logrus.Fields{
            "uri":      req.RequestURI,
            "method":   req.Method,
            "status":   responseData.status, // get captured status code
            "duration": duration,
            "size":     responseData.size, // get captured size
        }).Info("request completed")
    }
    return http.HandlerFunc(loggingFn)
}

Lets run and see the logs:

$ go run main.go
INFO[0000] starting server    addr="127.0.0.1:8080"                               
INFO[0002] request completed    duration="13.642µs" method=GET size=4 status=200 uri=/ping

As you can see the response details are logged as well.

Links

The full code is available in GitHub Gist: Simple GoLang HTTP Logging Middleware.

Originally published at https://arunvelsriram.dev.