summaryrefslogtreecommitdiff
path: root/modules
diff options
context:
space:
mode:
authorMatt Holt <mholt@users.noreply.github.com>2023-10-11 13:36:20 -0600
committerGitHub <noreply@github.com>2023-10-11 13:36:20 -0600
commit3a3182fba3eb20c45dce3efd9eb2856288a5ae04 (patch)
treebba97c2f5d10d86a54ff4c891a8adc2563b3f581 /modules
parente8b8d4a8cdf116bf05345443e37a21ea7a37b8bb (diff)
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 <lavofr@gmail.com> * Update modules/caddyhttp/reverseproxy/streaming.go Co-authored-by: Francis Lavoie <lavofr@gmail.com> * Add opt-in `trace_logs` option * Rename to VerboseLogs --------- Co-authored-by: Francis Lavoie <lavofr@gmail.com>
Diffstat (limited to 'modules')
-rw-r--r--modules/caddyhttp/reverseproxy/caddyfile.go7
-rw-r--r--modules/caddyhttp/reverseproxy/reverseproxy.go21
-rw-r--r--modules/caddyhttp/reverseproxy/streaming.go36
-rw-r--r--modules/caddyhttp/reverseproxy/streaming_test.go4
4 files changed, 62 insertions, 6 deletions
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 <size>
// stream_timeout <duration>
// stream_close_delay <duration>
+// trace_logs
//
// # request manipulation
// trusted_proxies [private_ranges] <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)
}