From c2ea96190944d8e39b0c200e43b1eedfeeeb49a6 Mon Sep 17 00:00:00 2001 From: Kegsay Date: Wed, 15 Apr 2020 17:48:40 +0100 Subject: [PATCH] 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 | 55 ++++++++++++++++++++++++++++++++++++++++++++++- go.mod | 1 + go.sum | 3 +++ 3 files changed, 58 insertions(+), 1 deletion(-) diff --git a/common/httpapi.go b/common/httpapi.go index 843336f5..e5324bd1 100644 --- a/common/httpapi.go +++ b/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) diff --git a/go.mod b/go.mod index 20235ae3..a8f442d5 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 5b4579bb..5c4e809f 100644 --- a/go.sum +++ b/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=