Go - Logging responses to incoming HTTP requests i

Question

This is a follow-up question to In go, how to inspect the http response that is written to http.ResponseWriter? since the solution there requires faking a request, which works great for a unit test but not on a live server.

I would like to dump out HTTP response that my web service is returning in response to requests it receives from users into a log file (or to console). The output should tell me what the headers are and the JSON payload.

How does one go about that?

If there were a httputil.DumpResponse equivalent that takes a http.ResponseWriter as argument rather than http.Response it would be perfect, but currently I can only access the Header from http.ResponseWriter

r = mux.NewRouter()
r.HandleFunc("/path", func (w http.ResponseWriter, r *http.Request) {

    fmt.Printf("r.HandleFunc /path\n")

    resp := server.NewResponse()
    defer resp.Close()

    r.ParseForm()

    // Server does some work here
    // ...

    // Insert debug code here, something like
    //
    // dump = http.DumpResponseFromWriter(w)
    // fmt.Printf("%s\n", dump)
});
http.Handle("/path", r)

Answer 1

This can be achieved by using a custom ServerMux that does no routing, but replaces the response writer, and then forwards the request to a normal mux. Since ResponseWriter is just an interface we can fake it easily.

First, we wrap the ResponseWriter interface with our own response writer, that will log everything and pass all functionality to a real response writer:

type DumpResponseWriter struct {
    // the underlying writer
    w http.ResponseWriter
    // more stuff you want to use for logging context (ip, headers, etc) here
}


func (w *DumpResponseWriter)Header() http.Header {
    return w.w.Header()
}

func (w *DumpResponseWriter)Write(b []byte) (int, error) {
        // You can add more context about the connection when initializing the writer and log it here
        log.Println("Writing < more context details here> ", string(b) )
        return w.w.Write(b)
}


func (w *DumpResponseWriter)WriteHeader(h int) {
    log.Println("Writing Header< more context details here> ", h)
    w.w.WriteHeader(h)
}

This leaves our handler func the same as before, and agnostic to the fact that we're using a "Fake" writer...

func MyHandler(w http.ResponseWriter, r *http.Request) {

    w.Write([]byte("Hello world"))
}

And then we simply replace the default mux with our own proxy mux, that replaces the writer and lets a regular ServeMux do its thing:

func main(){

    // we don't use the default mux, but a custom one
    mux := http.NewServeMux()
    mux.HandleFunc("/", MyHandler)

    // now we intercept each request and forward it to the mux to do    the routing to the handlers.
    err := http.ListenAndServe(":1337", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    // we wrap the response writer with our own. Add more context here if you want to the writer's instance
        writer := &DumpResponseWriter{w}

        // and we let our ordinary mux take care of things from here
        mux.ServeHTTP(writer, r)

        // We can also dump the headers after the handler is done. It will not print the standard headers though
        log.Printf("Response headers: %#v", w.Header())

    }))
    if err != nil {
        panic(err)
    }
}

http://play.golang.org/p/hT1PCNxI-V

Answer 2

Middleware Chaining

A common solution to this problem is the so called middleware chain. There are several libraries that provide this functionality e.g. negroni.

It's a form of continuation-passing style where you write your middleware functions like this (taken from negroni's readme):

func MyMiddleware(rw http.ResponseWriter, r *http.Request, next http.HandlerFunc) {
  // do some stuff before
  next(rw, r)
  // do some stuff after
}

And then negroni gives you an HTTP handler that calls your middlewares in the right order.

We could implement this solution slightly differently to a less magical and more functional (as in functional programming) approach. Define handler combinators as follows:

func NewFooHandler(next http.HandlerFunc) http.HandlerFunc {
    return func(w http.ResponseWriter, r *http.Request) {
        // do some stuff before
        next(r,w)
        // do some stuff after
    }
}

Then define your chain as a combination:

h := NewFooHandler(NewBarHandler(NewBazHandler(Sink)))

Now h is an http.HandlerFunc that does foo, then bar, then baz. Sink is just an empty last handler, that does nothing (to "finish" the chain.)

Applying this solution to your problem

Define a handler combinator:

func NewResponseLoggingHandler(next http.HandlerFunc) http.HandlerFunc {
    return func(w http.ResponseWriter, r *http.Request) {

        // switch out response writer for a recorder
        // for all subsequent handlers
        c := httptest.NewRecorder()
        next(c, r)

        // copy everything from response recorder
        // to actual response writer
        for k, v := range c.HeaderMap {
            w.Header()[k] = v
        }
        w.WriteHeader(c.Code)
        c.Body.WriteTo(w)

    }
}

Now the problem boils down to handler management. You'll probably want this handler applied to all chains in a certain category. For this, you can use combinators again (this is somewhat equivalent to negroni's Classic() method):

func NewDefaultHandler(next http.HandlerFunc) http.HandlerFunc {
    return NewResponseLoggingHandler(NewOtherStuffHandler(next))
}

After this, whenever you start a chain like this:

h := NewDefaultHandler(...)

It will automatically include response logging and all the default stuff that you defined in NewDefaultHandler.

Answer 3

Implementing Mat Ryer's approach with logging request id based on httptest.ResponseRecorder

Disadvantages of using httptest.ResponseRecorder:

• HTTP/1.1 only
• Doesn't supports ReadFrom(), Hijack(), Flush() maybe something else
• Headers like Content-Length and Date are not available in recorder

Code:

import (
    "fmt"
    "github.com/google/uuid"
    "log"
    "net/http"
    "net/http/httptest"
    "net/http/httputil"
    "strings"
)

func main() {
    logger := log.New(os.Stdout, "server: ", log.Lshortfile)
    http.HandleFunc("/api/smth", Adapt(smth, httpLogger(quips.logger)))
    panic(http.ListenAndServe(":8080", nil))
}

type Adapter func(http.HandlerFunc) http.HandlerFunc

func Adapt(h http.HandlerFunc, adapters ...Adapter) http.HandlerFunc {
    for _, adapter := range adapters {
        h = adapter(h)
    }
    return h
}

func httpLogger(logger *log.Logger) Adapter {
    return func(h http.HandlerFunc) http.HandlerFunc {
        return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
            dumpBody := true
            if r.ContentLength > 1024 {
                dumpBody = false
            }
            dump, err := httputil.DumpRequest(r, dumpBody)
            if err != nil {
                http.Error(w, fmt.Sprint(err), http.StatusInternalServerError)
                return
            }

            reqId, err := uuid.NewRandom()
            if err != nil {
                http.Error(w, fmt.Sprint(err), http.StatusInternalServerError)
                return
            }

            logger.Printf("<<<<< Request %s\n%s\n<<<<<", reqId.String(), string(dump))

            recorder := httptest.NewRecorder()
            defer func() {
                var sb strings.Builder
                fmt.Fprintf(&sb, "%s %d\n", recorder.Result().Proto, recorder.Result().StatusCode)

                for h, v := range recorder.Result().Header {
                    w.Header()[h] = v
                    for _, headerValue := range v {
                        fmt.Fprintf(&sb, "%s: %s\n", h, headerValue)
                    }
                }
                w.Header().Set("X-Request-Id", reqId.String())
                fmt.Fprintf(&sb, "X-Request-Id: %s\n", reqId.String())
                fmt.Fprintf(&sb, "Content-Length: %d\n", recorder.Body.Len())
                fmt.Fprint(&sb, "\n")
                sb.Write(recorder.Body.Bytes())

                logger.Printf(">>>>> Response %s\n%s\n>>>>>", reqId.String(), sb.String())

                w.WriteHeader(recorder.Result().StatusCode)
                recorder.Body.WriteTo(w)
            }()
            h.ServeHTTP(recorder, r)
        })
    }
}