reverseproxy: Minor logging improvements

caddyserver · May 5, 2021 · a17c3b5 · a17c3b5
1 parent 74f5d66
commit a17c3b5
Show file tree

Hide file tree

Showing 3 changed files with 16 additions and 6 deletions.
diff --git 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
@@ -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
@@ -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)