Logging responses to incoming HTTP requests inside http.HandleFunc
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.
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
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-LengthandDateare 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)
})
}
}