Add HTTP request debug logging (#300)

Signed-off-by: Bill Farner <[email protected]>

Author: wfarner

Makefile

@@ -84,13 +84,13 @@ endif
 	$(call build_binary,infrakit,github.com/docker/infrakit/cmd/cli)
 	$(call build_binary,infrakit-manager,github.com/docker/infrakit/cmd/manager)
 	$(call build_binary,infrakit-group-default,github.com/docker/infrakit/cmd/group)
-	$(call build_binary,infrakit-flavor-combo,github.com/docker/infrakit/example/flavor/combo)
-	$(call build_binary,infrakit-flavor-swarm,github.com/docker/infrakit/example/flavor/swarm)
-	$(call build_binary,infrakit-flavor-vanilla,github.com/docker/infrakit/example/flavor/vanilla)
-	$(call build_binary,infrakit-flavor-zookeeper,github.com/docker/infrakit/example/flavor/zookeeper)
-	$(call build_binary,infrakit-instance-file,github.com/docker/infrakit/example/instance/file)
-	$(call build_binary,infrakit-instance-terraform,github.com/docker/infrakit/example/instance/terraform)
-	$(call build_binary,infrakit-instance-vagrant,github.com/docker/infrakit/example/instance/vagrant)
+	$(call build_binary,infrakit-flavor-combo,github.com/docker/infrakit/pkg/example/flavor/combo)
+	$(call build_binary,infrakit-flavor-swarm,github.com/docker/infrakit/pkg/example/flavor/swarm)
+	$(call build_binary,infrakit-flavor-vanilla,github.com/docker/infrakit/pkg/example/flavor/vanilla)
+	$(call build_binary,infrakit-flavor-zookeeper,github.com/docker/infrakit/pkg/example/flavor/zookeeper)
+	$(call build_binary,infrakit-instance-file,github.com/docker/infrakit/pkg/example/instance/file)
+	$(call build_binary,infrakit-instance-terraform,github.com/docker/infrakit/pkg/example/instance/terraform)
+	$(call build_binary,infrakit-instance-vagrant,github.com/docker/infrakit/pkg/example/instance/vagrant)
 
 install:
 	@echo "+ $@"

pkg/rpc/client/client.go

@@ -2,9 +2,11 @@ package client
 
 import (
 	"bytes"
+	log "github.com/Sirupsen/logrus"
 	"github.com/gorilla/rpc/v2/json"
 	"net"
 	"net/http"
+	"net/http/httputil"
 )
 
 // Client is an HTTP client for sending JSON-RPC requests.
@@ -28,12 +30,32 @@ func (c Client) Call(method string, arg interface{}, result interface{}) error {
 		return err
 	}
 
+	req, err := http.NewRequest("POST", "http:///", bytes.NewReader(message))
+	if err != nil {
+		return err
+	}
+	req.Header.Set("Content-Type", "application/json")
+
+	requestData, err := httputil.DumpRequest(req, true)
+	if err == nil {
+		log.Debugf("Sending request %s", string(requestData))
+	} else {
+		log.Error(err)
+	}
+
 	resp, err := c.http.Post("http://d/rpc", "application/json", bytes.NewReader(message))
 	if err != nil {
 		return err
 	}
 
 	defer resp.Body.Close()
 
+	responseData, err := httputil.DumpResponse(resp, true)
+	if err == nil {
+		log.Debugf("Received response %s", string(responseData))
+	} else {
+		log.Error(err)
+	}
+
 	return json.DecodeClientResponse(resp.Body, result)
 }

pkg/rpc/server/server.go

@@ -8,9 +8,10 @@ import (
 	"net/http"
 	"time"
 
-	"github.com/gorilla/handlers"
 	"github.com/gorilla/rpc/v2"
 	"github.com/gorilla/rpc/v2/json"
+	"net/http/httptest"
+	"net/http/httputil"
 )
 
 // Stoppable support proactive stopping, and blocking until stopped.
@@ -31,6 +32,33 @@ func (s *stoppableServer) AwaitStopped() {
 	<-s.server.StopChan()
 }
 
+type loggingHandler struct {
+	handler http.Handler
+}
+
+func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
+	requestData, err := httputil.DumpRequest(req, true)
+	if err == nil {
+		log.Debugf("Received request %s", string(requestData))
+	} else {
+		log.Error(err)
+	}
+
+	recorder := httptest.NewRecorder()
+
+	h.handler.ServeHTTP(recorder, req)
+
+	responseData, err := httputil.DumpResponse(recorder.Result(), true)
+	if err == nil {
+		log.Debugf("Sending response %s", string(responseData))
+	} else {
+		log.Error(err)
+	}
+
+	w.WriteHeader(recorder.Code)
+	recorder.Body.WriteTo(w)
+}
+
 // StartPluginAtPath starts an HTTP server listening on a unix socket at the specified path.
 // Returns a Stoppable that can be used to stop or block on the server.
 func StartPluginAtPath(socketPath string, receiver interface{}) (Stoppable, error) {
@@ -44,7 +72,7 @@ func StartPluginAtPath(socketPath string, receiver interface{}) (Stoppable, erro
 	httpLog := log.New()
 	httpLog.Level = log.GetLevel()
 
-	handler := handlers.LoggingHandler(httpLog.WriterLevel(log.DebugLevel), server)
+	handler := loggingHandler{handler: server}
 	gracefulServer := graceful.Server{
 		Timeout: 10 * time.Second,
 		Server:  &http.Server{Addr: fmt.Sprintf("unix://%s", socketPath), Handler: handler},