reverseproxy: Minor logging improvements

This commit is contained in:
Matthew Holt 2021-05-05 14:52:18 -06:00
parent 74f5d66c48
commit a17c3b568d
No known key found for this signature in database
GPG key ID: 2A349DD577D586A5
3 changed files with 16 additions and 6 deletions

View file

@ -568,9 +568,11 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, repl *
logger := h.logger.With( logger := h.logger.With(
zap.String("upstream", di.Upstream.String()), zap.String("upstream", di.Upstream.String()),
zap.Object("request", caddyhttp.LoggableHTTPRequest{Request: req}), zap.Object("request", caddyhttp.LoggableHTTPRequest{Request: req}),
zap.Duration("duration", duration)) )
if err != nil { if err != nil {
logger.Debug("upstream roundtrip", zap.Error(err)) logger.Debug("upstream roundtrip",
zap.Duration("duration", duration),
zap.Error(err))
return err return err
} }
logger.Debug("upstream roundtrip", 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) // deal with 101 Switching Protocols responses: (WebSocket, h2c, etc)
if res.StatusCode == http.StatusSwitchingProtocols { if res.StatusCode == http.StatusSwitchingProtocols {
h.handleUpgradeResponse(rw, req, res) h.handleUpgradeResponse(logger, rw, req, res)
return nil return nil
} }

View file

@ -366,7 +366,7 @@ func TestCookieHashPolicy(t *testing.T) {
h := cookieHashPolicy.Select(pool, request, w) h := cookieHashPolicy.Select(pool, request, w)
cookieServer1 := w.Result().Cookies()[0] cookieServer1 := w.Result().Cookies()[0]
if cookieServer1 == nil { if cookieServer1 == nil {
t.Error("cookieHashPolicy should set a cookie") t.Fatal("cookieHashPolicy should set a cookie")
} }
if cookieServer1.Name != "lb" { if cookieServer1.Name != "lb" {
t.Error("cookieHashPolicy should set a cookie with name lb") t.Error("cookieHashPolicy should set a cookie with name lb")

View file

@ -29,7 +29,7 @@ import (
"go.uber.org/zap" "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) reqUpType := upgradeType(req.Header)
resUpType := upgradeType(res.Header) resUpType := upgradeType(res.Header)
if reqUpType != resUpType { if reqUpType != resUpType {
@ -65,12 +65,19 @@ func (h Handler) handleUpgradeResponse(rw http.ResponseWriter, req *http.Request
}() }()
defer close(backConnCloseCh) defer close(backConnCloseCh)
logger.Debug("upgrading connection")
conn, brw, err := hj.Hijack() conn, brw, err := hj.Hijack()
if err != nil { 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 return
} }
defer conn.Close() 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 res.Body = nil // so res.Write only writes the headers; we have res.Body in backConn above
if err := res.Write(brw); err != nil { if err := res.Write(brw); err != nil {
h.logger.Debug("response write", zap.Error(err)) 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)) h.logger.Debug("response flush", zap.Error(err))
return return
} }
errc := make(chan error, 1) errc := make(chan error, 1)
spc := switchProtocolCopier{user: conn, backend: backConn} spc := switchProtocolCopier{user: conn, backend: backConn}
go spc.copyToBackend(errc) go spc.copyToBackend(errc)