From a17c3b568d635ea45deb204d06e251810e94a7d6 Mon Sep 17 00:00:00 2001 From: Matthew Holt Date: Wed, 5 May 2021 14:52:18 -0600 Subject: reverseproxy: Minor logging improvements --- modules/caddyhttp/reverseproxy/reverseproxy.go | 8 +++++--- modules/caddyhttp/reverseproxy/selectionpolicies_test.go | 2 +- modules/caddyhttp/reverseproxy/streaming.go | 12 ++++++++++-- 3 files changed, 16 insertions(+), 6 deletions(-) (limited to 'modules') diff --git a/modules/caddyhttp/reverseproxy/reverseproxy.go b/modules/caddyhttp/reverseproxy/reverseproxy.go index b6c24f3..ddb3ca9 100644 --- a/modules/caddyhttp/reverseproxy/reverseproxy.go +++ b/modules/caddyhttp/reverseproxy/reverseproxy.go @@ -568,9 +568,11 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, repl * logger := h.logger.With( zap.String("upstream", di.Upstream.String()), zap.Object("request", caddyhttp.LoggableHTTPRequest{Request: req}), - zap.Duration("duration", duration)) + ) if err != nil { - logger.Debug("upstream roundtrip", zap.Error(err)) + logger.Debug("upstream roundtrip", + zap.Duration("duration", duration), + zap.Error(err)) return err } logger.Debug("upstream roundtrip", @@ -642,7 +644,7 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, repl * // deal with 101 Switching Protocols responses: (WebSocket, h2c, etc) if res.StatusCode == http.StatusSwitchingProtocols { - h.handleUpgradeResponse(rw, req, res) + h.handleUpgradeResponse(logger, rw, req, res) return nil } diff --git a/modules/caddyhttp/reverseproxy/selectionpolicies_test.go b/modules/caddyhttp/reverseproxy/selectionpolicies_test.go index 60a2702..c28799d 100644 --- a/modules/caddyhttp/reverseproxy/selectionpolicies_test.go +++ b/modules/caddyhttp/reverseproxy/selectionpolicies_test.go @@ -366,7 +366,7 @@ func TestCookieHashPolicy(t *testing.T) { h := cookieHashPolicy.Select(pool, request, w) cookieServer1 := w.Result().Cookies()[0] if cookieServer1 == nil { - t.Error("cookieHashPolicy should set a cookie") + t.Fatal("cookieHashPolicy should set a cookie") } if cookieServer1.Name != "lb" { t.Error("cookieHashPolicy should set a cookie with name lb") diff --git a/modules/caddyhttp/reverseproxy/streaming.go b/modules/caddyhttp/reverseproxy/streaming.go index f108a97..285c04b 100644 --- a/modules/caddyhttp/reverseproxy/streaming.go +++ b/modules/caddyhttp/reverseproxy/streaming.go @@ -29,7 +29,7 @@ import ( "go.uber.org/zap" ) -func (h Handler) handleUpgradeResponse(rw http.ResponseWriter, req *http.Request, res *http.Response) { +func (h Handler) handleUpgradeResponse(logger *zap.Logger, rw http.ResponseWriter, req *http.Request, res *http.Response) { reqUpType := upgradeType(req.Header) resUpType := upgradeType(res.Header) if reqUpType != resUpType { @@ -65,12 +65,19 @@ func (h Handler) handleUpgradeResponse(rw http.ResponseWriter, req *http.Request }() defer close(backConnCloseCh) + logger.Debug("upgrading connection") conn, brw, err := hj.Hijack() if err != nil { - h.logger.Error("Hijack failed on protocol switch", zap.Error(err)) + h.logger.Error("hijack failed on protocol switch", zap.Error(err)) return } defer conn.Close() + + start := time.Now() + defer func() { + logger.Debug("connection closed", zap.Duration("duration", time.Since(start))) + }() + res.Body = nil // so res.Write only writes the headers; we have res.Body in backConn above if err := res.Write(brw); err != nil { h.logger.Debug("response write", zap.Error(err)) @@ -80,6 +87,7 @@ func (h Handler) handleUpgradeResponse(rw http.ResponseWriter, req *http.Request h.logger.Debug("response flush", zap.Error(err)) return } + errc := make(chan error, 1) spc := switchProtocolCopier{user: conn, backend: backConn} go spc.copyToBackend(errc) -- cgit v1.2.3