Logging http responses (in addition to requests)

Question

I am using Go and the Gorilla web toolkit's mux and handler packages to build a complex application, part of which requires a http server. Gorilla's mux and handler packages work wonderfully and I am able to successfully get the http server up and running and it has been quite simple to log requests.

However, I am unable to determine how I may log responses. Ideally, I would like a mechanism, similar to Gorilla's LoggingHandler, that "wraps" the logging mechanism easily.

Is there a Go package that does easily wraps / logs responses? Is there a way to use Go or Gorilla's capabilities in this fashion that I have not considered?

Rici

Answer 1

Thanks for the great suggestions. I tried a few of the suggestions and landed on a rather simple solution that uses a minimalist wrapper. Here is the solution that worked for me (feel free to offer comments, or better yet, other solutions):

import (
    "fmt"
    "log"
    "net/http"
    "net/http/httptest"
    "net/http/httputil"
    "github.com/gorilla/mux"
)
:

func logHandler(fn http.HandlerFunc) http.HandlerFunc {
    return func(w http.ResponseWriter, r *http.Request) {
        x, err := httputil.DumpRequest(r, true)
        if err != nil {
            http.Error(w, fmt.Sprint(err), http.StatusInternalServerError)
            return
        }
        log.Println(fmt.Sprintf("%q", x))
        rec := httptest.NewRecorder()
        fn(rec, r)
        log.Println(fmt.Sprintf("%q", rec.Body))            
    }
}

func MessageHandler(w http.ResponseWriter, r *http.Request) {
    fmt.Fprintln(w, "A message was received")
}

And the following code will use the aforementioned handler:

:
router := mux.NewRouter()
router.HandleFunc("/", logHandler(MessageHandler))
:

Output from the above code will be something along the lines of:

:
2016/07/20 14:44:29 "GET ... HTTP/1.1\r\nHost: localhost:8088\r\nAccept: */*\r\nUser-Agent: curl/7.43.0\r\n\r\n"
2016/07/20 14:44:29 ...[response body]
:

Rici

This solution will not deterministically work with the popular justinas/alice middleware chaining library. From the justinas/alice/README.md: "Note that Alice makes no guarantees for how one or another piece of middleware will behave. Once it passes the execution to the outer layer of middleware, it has no saying in whether middleware will execute the inner handlers. This is intentional behavior." – Peep

just a suggestion: log.Printf("%q\n", x) may make your log lines cleaner. Additionally, error's have an .Error() func that returns the string repr of the error so you can avoid doing fmt.Sprintf(err). In fact, under the fmt hood is exactly what they do for errors – Salivation

Answer 2

The accepted answer by Eric Broda won't help much if you want to actually send your response to the client. I've made a modification to that code that will actually work:

func logHandler(fn http.HandlerFunc) http.HandlerFunc {
    return func(w http.ResponseWriter, r *http.Request) {
        x, err := httputil.DumpRequest(r, true)
        if err != nil {
            http.Error(w, fmt.Sprint(err), http.StatusInternalServerError)
            return
        }
        log.Println(fmt.Sprintf("%q", x))
        rec := httptest.NewRecorder()
        fn(rec, r)
        log.Println(fmt.Sprintf("%q", rec.Body))        

        // this copies the recorded response to the response writer
        for k, v := range rec.HeaderMap {
            w.Header()[k] = v
        }
        w.WriteHeader(rec.Code)
        rec.Body.WriteTo(w)
    }
}

Nest

Answer 3

edit sorry, I didn't notice your mention of gorilla-mux, I have only tried this with gin, but if it uses middlewares this should still work.

---

the trick is, c.Next() in a middleware blocks until all subsequent middlewares return. Here's a logrus solution. Put this as your first middleware:

func Logrus(logger *logrus.Logger) gin.HandlerFunc {
    return func(c *gin.Context) {
        start := time.Now().UTC()
        path := c.Request.URL.Path
        c.Next()
        end := time.Now().UTC()
        latency := end.Sub(start)
        logger.WithFields(logrus.Fields{
            "status":     c.Writer.Status(),
            "method":     c.Request.Method,
            "path":       path,
            "ip":         c.ClientIP(),
            "duration":   latency,
            "user_agent": c.Request.UserAgent(),
        }).Info()
    }
}
GinEngine.Use(Logrus(logrus.StandardLogger()))

Rosalvarosalyn