From 3a3182fba3eb20c45dce3efd9eb2856288a5ae04 Mon Sep 17 00:00:00 2001 From: Matt Holt Date: Wed, 11 Oct 2023 13:36:20 -0600 Subject: reverseproxy: Add more debug logs (#5793) * reverseproxy: Add more debug logs This makes debug logging very noisy when reverse proxying, but I guess that's the point. This has shown to be useful in troubleshooting infrastructure issues. * Update modules/caddyhttp/reverseproxy/streaming.go Co-authored-by: Francis Lavoie * Update modules/caddyhttp/reverseproxy/streaming.go Co-authored-by: Francis Lavoie * Add opt-in `trace_logs` option * Rename to VerboseLogs --------- Co-authored-by: Francis Lavoie --- modules/caddyhttp/reverseproxy/caddyfile.go | 7 +++++ modules/caddyhttp/reverseproxy/reverseproxy.go | 21 ++++++++++++-- modules/caddyhttp/reverseproxy/streaming.go | 36 ++++++++++++++++++++++-- modules/caddyhttp/reverseproxy/streaming_test.go | 4 ++- 4 files changed, 62 insertions(+), 6 deletions(-) (limited to 'modules/caddyhttp') diff --git a/modules/caddyhttp/reverseproxy/caddyfile.go b/modules/caddyhttp/reverseproxy/caddyfile.go index 95293f0..bcbe744 100644 --- a/modules/caddyhttp/reverseproxy/caddyfile.go +++ b/modules/caddyhttp/reverseproxy/caddyfile.go @@ -90,6 +90,7 @@ func parseCaddyfile(h httpcaddyfile.Helper) (caddyhttp.MiddlewareHandler, error) // max_buffer_size // stream_timeout // stream_close_delay +// trace_logs // // # request manipulation // trusted_proxies [private_ranges] @@ -782,6 +783,12 @@ func (h *Handler) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { responseHandler, ) + case "verbose_logs": + if h.VerboseLogs { + return d.Err("verbose_logs already specified") + } + h.VerboseLogs = true + default: return d.Errf("unrecognized subdirective %s", d.Val()) } diff --git a/modules/caddyhttp/reverseproxy/reverseproxy.go b/modules/caddyhttp/reverseproxy/reverseproxy.go index 64a7d7a..08be40d 100644 --- a/modules/caddyhttp/reverseproxy/reverseproxy.go +++ b/modules/caddyhttp/reverseproxy/reverseproxy.go @@ -191,6 +191,13 @@ type Handler struct { // - `{http.reverse_proxy.header.*}` The headers from the response HandleResponse []caddyhttp.ResponseHandler `json:"handle_response,omitempty"` + // If set, the proxy will write very detailed logs about its + // inner workings. Enable this only when debugging, as it + // will produce a lot of output. + // + // EXPERIMENTAL: This feature is subject to change or removal. + VerboseLogs bool `json:"verbose_logs,omitempty"` + Transport http.RoundTripper `json:"-"` CB CircuitBreaker `json:"-"` DynamicUpstreams UpstreamSource `json:"-"` @@ -943,9 +950,15 @@ func (h *Handler) finalizeResponse( } rw.WriteHeader(res.StatusCode) + if h.VerboseLogs { + logger.Debug("wrote header") + } - err := h.copyResponse(rw, res.Body, h.flushInterval(req, res)) - res.Body.Close() // close now, instead of defer, to populate res.Trailer + err := h.copyResponse(rw, res.Body, h.flushInterval(req, res), logger) + errClose := res.Body.Close() // close now, instead of defer, to populate res.Trailer + if h.VerboseLogs || errClose != nil { + logger.Debug("closed response body from upstream", zap.Error(errClose)) + } if err != nil { // we're streaming the response and we've already written headers, so // there's nothing an error handler can do to recover at this point; @@ -979,6 +992,10 @@ func (h *Handler) finalizeResponse( } } + if h.VerboseLogs { + logger.Debug("response finalized") + } + return nil } diff --git a/modules/caddyhttp/reverseproxy/streaming.go b/modules/caddyhttp/reverseproxy/streaming.go index c5369d8..155a1df 100644 --- a/modules/caddyhttp/reverseproxy/streaming.go +++ b/modules/caddyhttp/reverseproxy/streaming.go @@ -184,15 +184,22 @@ func (h Handler) isBidirectionalStream(req *http.Request, res *http.Response) bo (ae == "identity" || ae == "") } -func (h Handler) copyResponse(dst http.ResponseWriter, src io.Reader, flushInterval time.Duration) error { +func (h Handler) copyResponse(dst http.ResponseWriter, src io.Reader, flushInterval time.Duration, logger *zap.Logger) error { var w io.Writer = dst if flushInterval != 0 { + var mlwLogger *zap.Logger + if h.VerboseLogs { + mlwLogger = logger.Named("max_latency_writer") + } else { + mlwLogger = zap.NewNop() + } mlw := &maxLatencyWriter{ dst: dst, //nolint:bodyclose flush: http.NewResponseController(dst).Flush, latency: flushInterval, + logger: mlwLogger, } defer mlw.stop() @@ -205,19 +212,30 @@ func (h Handler) copyResponse(dst http.ResponseWriter, src io.Reader, flushInter buf := streamingBufPool.Get().(*[]byte) defer streamingBufPool.Put(buf) - _, err := h.copyBuffer(w, src, *buf) + + var copyLogger *zap.Logger + if h.VerboseLogs { + copyLogger = logger + } else { + copyLogger = zap.NewNop() + } + + _, err := h.copyBuffer(w, src, *buf, copyLogger) return err } // copyBuffer returns any write errors or non-EOF read errors, and the amount // of bytes written. -func (h Handler) copyBuffer(dst io.Writer, src io.Reader, buf []byte) (int64, error) { +func (h Handler) copyBuffer(dst io.Writer, src io.Reader, buf []byte, logger *zap.Logger) (int64, error) { if len(buf) == 0 { buf = make([]byte, defaultBufferSize) } var written int64 for { + logger.Debug("waiting to read from upstream") nr, rerr := src.Read(buf) + logger := logger.With(zap.Int("read", nr)) + logger.Debug("read from upstream", zap.Error(rerr)) if rerr != nil && rerr != io.EOF && rerr != context.Canceled { // TODO: this could be useful to know (indeed, it revealed an error in our // fastcgi PoC earlier; but it's this single error report here that necessitates @@ -229,10 +247,15 @@ func (h Handler) copyBuffer(dst io.Writer, src io.Reader, buf []byte) (int64, er h.logger.Error("reading from backend", zap.Error(rerr)) } if nr > 0 { + logger.Debug("writing to downstream") nw, werr := dst.Write(buf[:nr]) if nw > 0 { written += int64(nw) } + logger.Debug("wrote to downstream", + zap.Int("written", nw), + zap.Int64("written_total", written), + zap.Error(werr)) if werr != nil { return written, fmt.Errorf("writing: %w", werr) } @@ -452,18 +475,22 @@ type maxLatencyWriter struct { mu sync.Mutex // protects t, flushPending, and dst.Flush t *time.Timer flushPending bool + logger *zap.Logger } func (m *maxLatencyWriter) Write(p []byte) (n int, err error) { m.mu.Lock() defer m.mu.Unlock() n, err = m.dst.Write(p) + m.logger.Debug("wrote bytes", zap.Int("n", n), zap.Error(err)) if m.latency < 0 { + m.logger.Debug("flushing immediately") //nolint:errcheck m.flush() return } if m.flushPending { + m.logger.Debug("delayed flush already pending") return } if m.t == nil { @@ -471,6 +498,7 @@ func (m *maxLatencyWriter) Write(p []byte) (n int, err error) { } else { m.t.Reset(m.latency) } + m.logger.Debug("timer set for delayed flush", zap.Duration("duration", m.latency)) m.flushPending = true return } @@ -479,8 +507,10 @@ func (m *maxLatencyWriter) delayedFlush() { m.mu.Lock() defer m.mu.Unlock() if !m.flushPending { // if stop was called but AfterFunc already started this goroutine + m.logger.Debug("delayed flush is not pending") return } + m.logger.Debug("delayed flush") //nolint:errcheck m.flush() m.flushPending = false diff --git a/modules/caddyhttp/reverseproxy/streaming_test.go b/modules/caddyhttp/reverseproxy/streaming_test.go index 919538f..3f6da2f 100644 --- a/modules/caddyhttp/reverseproxy/streaming_test.go +++ b/modules/caddyhttp/reverseproxy/streaming_test.go @@ -5,6 +5,8 @@ import ( "net/http/httptest" "strings" "testing" + + "github.com/caddyserver/caddy/v2" ) func TestHandlerCopyResponse(t *testing.T) { @@ -22,7 +24,7 @@ func TestHandlerCopyResponse(t *testing.T) { for _, d := range testdata { src := bytes.NewBuffer([]byte(d)) dst.Reset() - err := h.copyResponse(recorder, src, 0) + err := h.copyResponse(recorder, src, 0, caddy.Log()) if err != nil { t.Errorf("failed with error: %v", err) } -- cgit v1.2.3