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.

Open Source | DevOps | Infrastructure | Backend | Ployglot Programmer