Add HTTP trace logging (#965)

* Dump all requests/response server-side

* Wrap in DENDRITE_TRACE

* DENDRITE_TRACE_HTTP is better

* Bugfix for response body and linting

* False is true and true is false

* Linting

* How did this get missed

* More linting

common/httpapi.go

@@ -1,7 +1,12 @@
 package common
 
 import (
+	"io"
 	"net/http"
+	"net/http/httptest"
+	"net/http/httputil"
+	"os"
+	"strings"
 	"time"
 
 	"github.com/matrix-org/dendrite/clientapi/auth"
@@ -46,12 +51,60 @@ func MakeAuthAPI(
 // MakeExternalAPI turns a util.JSONRequestHandler function into an http.Handler.
 // This is used for APIs that are called from the internet.
 func MakeExternalAPI(metricsName string, f func(*http.Request) util.JSONResponse) http.Handler {
+	// TODO: We shouldn't be directly reading env vars here, inject it in instead.
+	// Refactor this when we split out config structs.
+	verbose := false
+	if os.Getenv("DENDRITE_TRACE_HTTP") == "1" {
+		verbose = true
+	}
 	h := util.MakeJSONAPI(util.NewJSONRequestHandler(f))
 	withSpan := func(w http.ResponseWriter, req *http.Request) {
+		nextWriter := w
+		if verbose {
+			logger := logrus.NewEntry(logrus.StandardLogger())
+			// Log outgoing response
+			rec := httptest.NewRecorder()
+			nextWriter = rec
+			defer func() {
+				resp := rec.Result()
+				dump, err := httputil.DumpResponse(resp, true)
+				if err != nil {
+					logger.Debugf("Failed to dump outgoing response: %s", err)
+				} else {
+					strSlice := strings.Split(string(dump), "\n")
+					for _, s := range strSlice {
+						logger.Debug(s)
+					}
+				}
+				// copy the response to the client
+				for hdr, vals := range resp.Header {
+					for _, val := range vals {
+						w.Header().Add(hdr, val)
+					}
+				}
+				w.WriteHeader(resp.StatusCode)
+				// discard errors as this is for debugging
+				_, _ = io.Copy(w, resp.Body)
+				_ = resp.Body.Close()
+			}()
+
+			// Log incoming request
+			dump, err := httputil.DumpRequest(req, true)
+			if err != nil {
+				logger.Debugf("Failed to dump incoming request: %s", err)
+			} else {
+				strSlice := strings.Split(string(dump), "\n")
+				for _, s := range strSlice {
+					logger.Debug(s)
+				}
+			}
+		}
+
 		span := opentracing.StartSpan(metricsName)
 		defer span.Finish()
 		req = req.WithContext(opentracing.ContextWithSpan(req.Context(), span))
-		h.ServeHTTP(w, req)
+		h.ServeHTTP(nextWriter, req)
+
 	}
 
 	return http.HandlerFunc(withSpan)

go.mod

@@ -26,6 +26,7 @@ require (
 	github.com/pierrec/lz4 v2.5.0+incompatible // indirect
 	github.com/pkg/errors v0.9.1
 	github.com/prometheus/client_golang v1.4.1
+	github.com/prometheus/common v0.9.1
 	github.com/rcrowley/go-metrics v0.0.0-20200313005456-10cdbea86bc0 // indirect
 	github.com/sirupsen/logrus v1.4.2
 	github.com/tidwall/gjson v1.6.0 // indirect

go.sum

@@ -10,8 +10,10 @@ github.com/Shopify/toxiproxy v2.1.4+incompatible h1:TKdv8HiTLgE5wdJuEML90aBgNWso
 github.com/Shopify/toxiproxy v2.1.4+incompatible/go.mod h1:OXgGpZ6Cli1/URJOF1DMxUHB2q5Ap20/P/eIdh4G0pI=
 github.com/aead/siphash v1.0.1/go.mod h1:Nywa3cDsYNNK3gaciGTWPwHt0wlpNV15vwmswBAUSII=
 github.com/alecthomas/template v0.0.0-20160405071501-a0175ee3bccc/go.mod h1:LOuyumcjzFXgccqObfd/Ljyb9UuFJ6TxHnclSeseNhc=
+github.com/alecthomas/template v0.0.0-20190718012654-fb15b899a751 h1:JYp7IbQjafoB+tBA3gMyHYHrpOtNuDiK/uB5uXxq5wM=
 github.com/alecthomas/template v0.0.0-20190718012654-fb15b899a751/go.mod h1:LOuyumcjzFXgccqObfd/Ljyb9UuFJ6TxHnclSeseNhc=
 github.com/alecthomas/units v0.0.0-20151022065526-2efee857e7cf/go.mod h1:ybxpYRFXyAe+OPACYpWeL0wqObRcbAqCMya13uyzqw0=
+github.com/alecthomas/units v0.0.0-20190717042225-c3de453c63f4 h1:Hs82Z41s6SdL1CELW+XaDYmOH4hkBN4/N9og/AsOv7E=
 github.com/alecthomas/units v0.0.0-20190717042225-c3de453c63f4/go.mod h1:ybxpYRFXyAe+OPACYpWeL0wqObRcbAqCMya13uyzqw0=
 github.com/armon/consul-api v0.0.0-20180202201655-eb2c6b5be1b6/go.mod h1:grANhF5doyWs3UAsr3K4I6qtAmlQcZDesFNEHPZAzj8=
 github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
@@ -688,6 +690,7 @@ google.golang.org/grpc v1.19.0/go.mod h1:mqu4LbDTu4XGKhr4mRzUsmM4RtVoemTSY81AxZi
 google.golang.org/grpc v1.20.1/go.mod h1:10oTOabMzJvdu6/UiuZezV6QK5dSlG84ov/aaiqXj38=
 gopkg.in/Shopify/sarama.v1 v1.20.1 h1:Gi09A3fJXm0Jgt8kuKZ8YK+r60GfYn7MQuEmI3oq6hE=
 gopkg.in/Shopify/sarama.v1 v1.20.1/go.mod h1:AxnvoaevB2nBjNK17cG61A3LleFcWFwVBHBt+cot4Oc=
+gopkg.in/alecthomas/kingpin.v2 v2.2.6 h1:jMFz6MfLP0/4fUyZle81rXUoxOBFi19VUFKVDOQfozc=
 gopkg.in/alecthomas/kingpin.v2 v2.2.6/go.mod h1:FMv+mEhP44yOT+4EoQTLFTRgOQ1FBLkstjWtayDeSgw=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=