From afb6020897df819f1f906f7172018a9c35fc2135 Mon Sep 17 00:00:00 2001 From: Bill Farner Date: Tue, 15 Nov 2016 14:19:17 -0800 Subject: [PATCH 1/2] Add debug logging of full HTTP requests and responses Signed-off-by: Bill Farner --- Makefile | 14 +++++++------- pkg/rpc/server/server.go | 32 ++++++++++++++++++++++++++++++-- 2 files changed, 37 insertions(+), 9 deletions(-) diff --git a/Makefile b/Makefile index 752529ee4..deed50464 100644 --- a/Makefile +++ b/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 "+ $@" diff --git a/pkg/rpc/server/server.go b/pkg/rpc/server/server.go index 29eda4f0c..65e2f66d6 100644 --- a/pkg/rpc/server/server.go +++ b/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.Debug(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.Debug(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}, From 71acfa1219c6def06153ce871b5a530b656d0f05 Mon Sep 17 00:00:00 2001 From: Bill Farner Date: Tue, 15 Nov 2016 15:04:05 -0800 Subject: [PATCH 2/2] Add client logging --- pkg/rpc/client/client.go | 22 ++++++++++++++++++++++ pkg/rpc/server/server.go | 4 ++-- 2 files changed, 24 insertions(+), 2 deletions(-) diff --git a/pkg/rpc/client/client.go b/pkg/rpc/client/client.go index fdc5c645a..fbc8a14ed 100644 --- a/pkg/rpc/client/client.go +++ b/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,6 +30,19 @@ 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 @@ -35,5 +50,12 @@ func (c Client) Call(method string, arg interface{}, result interface{}) error { 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) } diff --git a/pkg/rpc/server/server.go b/pkg/rpc/server/server.go index 65e2f66d6..1c3b7d34a 100644 --- a/pkg/rpc/server/server.go +++ b/pkg/rpc/server/server.go @@ -39,7 +39,7 @@ type loggingHandler struct { func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { requestData, err := httputil.DumpRequest(req, true) if err == nil { - log.Debug(string(requestData)) + log.Debugf("Received request %s", string(requestData)) } else { log.Error(err) } @@ -50,7 +50,7 @@ func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { responseData, err := httputil.DumpResponse(recorder.Result(), true) if err == nil { - log.Debug(string(responseData)) + log.Debugf("Sending response %s", string(responseData)) } else { log.Error(err) }