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.

caddy.go

@@ -864,13 +864,21 @@ func Version() (simple, full string) {
 	// bi.Main... hopefully.
 	var module *debug.Module
 	bi, ok := debug.ReadBuildInfo()
-	if ok {
-		// find the Caddy module in the dependency list
-		for _, dep := range bi.Deps {
-			if dep.Path == ImportPath {
-				module = dep
-				break
-			}
+	if !ok {
+		if CustomVersion != "" {
+			full = CustomVersion
+			simple = CustomVersion
+			return
+		}
+		full = "unknown"
+		simple = "unknown"
+		return
+	}
+	// find the Caddy module in the dependency list
+	for _, dep := range bi.Deps {
+		if dep.Path == ImportPath {
+			module = dep
+			break
 		}
 	}
 	if module != nil {

cmd/cobra.go

@@ -101,7 +101,7 @@ const fullDocsFooter = `Full documentation is available at:
 https://caddyserver.com/docs/command-line`
 
 func init() {
-	rootCmd.SetHelpTemplate(rootCmd.HelpTemplate() + "\n" + fullDocsFooter + "\n")
+	rootCmd.SetHelpTemplate(rootCmd.HelpTemplate() + "\n" + fullDocsFooter)
 }
 
 func caddyCmdToCoral(caddyCmd Command) *cobra.Command {

modules/caddyhttp/matchers.go

@@ -123,7 +123,6 @@ type (
 	// keyed by the query keys, with an array of string values to match for that key.
 	// Query key matches are exact, but wildcards may be used for value matches. Both
 	// keys and values may be placeholders.
-	//
 	// An example of the structure to match `?key=value&topic=api&query=something` is:
 	//
 	// ```json
@@ -809,29 +808,19 @@ func (m MatchQuery) Match(r *http.Request) bool {
 		return false
 	}
 
-	for param, allowedVals := range m {
+	for param, vals := range m {
 		param = repl.ReplaceAll(param, "")
-		incomingVals, found := parsed[param]
+		paramVal, found := parsed[param]
 		if found {
-			for _, allowedVal := range allowedVals {
-				allowedVal = repl.ReplaceAll(allowedVal, "")
-				if allowedVal == "*" {
-					return true
-				}
-				matched := true
-				for _, incomingVal := range incomingVals {
-					if incomingVal != allowedVal {
-						matched = false
-						break
-					}
-				}
-				if matched {
+			for _, v := range vals {
+				v = repl.ReplaceAll(v, "")
+				if paramVal[0] == v || v == "*" {
 					return true
 				}
 			}
 		}
 	}
-	return len(m) == 0 && len(parsed) == 0
+	return len(m) == 0 && len(r.URL.Query()) == 0
 }
 
 // CELLibrary produces options that expose this matcher for use in CEL

modules/caddyhttp/matchers_test.go

@@ -718,7 +718,7 @@ func TestQueryMatcher(t *testing.T) {
 			expect:   true,
 		},
 		{
-			scenario: "non match against a wildcard",
+			scenario: "non match against a wildcarded",
 			match:    MatchQuery{"debug": []string{"*"}},
 			input:    "/?other=something",
 			expect:   false,
@@ -765,30 +765,6 @@ func TestQueryMatcher(t *testing.T) {
 			input:    "/?somekey=1",
 			expect:   true,
 		},
-		{
-			scenario: "don't match conflicting values",
-			match:    MatchQuery{"a": []string{"1"}},
-			input:    "/?a=1&a=2",
-			expect:   false,
-		},
-		{
-			scenario: "conflicting values are ambiguous with multiple match values",
-			match:    MatchQuery{"a": []string{"1", "2"}},
-			input:    "/?a=1&a=2",
-			expect:   false,
-		},
-		{
-			scenario: "repeated kv pairs in URI",
-			match:    MatchQuery{"a": []string{"1"}},
-			input:    "/?a=1&a=1",
-			expect:   true,
-		},
-		{
-			scenario: "TODO: it's unclear whether the values should be AND'ed or OR'ed", // perhaps multiple query matchers could be used to "and"
-			match:    MatchQuery{"a": []string{"1", "2"}},
-			input:    "/?a=2",
-			expect:   true,
-		},
 	} {
 
 		u, _ := url.Parse(tc.input)
@@ -801,7 +777,7 @@ func TestQueryMatcher(t *testing.T) {
 		req = req.WithContext(ctx)
 		actual := tc.match.Match(req)
 		if actual != tc.expect {
-			t.Errorf("Test %d %v: Expected %t, got %t for '%s' (%s)", i, tc.match, tc.expect, actual, tc.input, tc.scenario)
+			t.Errorf("Test %d %v: Expected %t, got %t for '%s'", i, tc.match, tc.expect, actual, tc.input)
 			continue
 		}
 	}

modules/caddyhttp/reverseproxy/reverseproxy.go

@@ -977,9 +977,11 @@ func (h Handler) finalizeResponse(
 	}
 
 	rw.WriteHeader(res.StatusCode)
+	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
+	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;
@@ -1014,6 +1016,8 @@ func (h Handler) finalizeResponse(
 		}
 	}
 
+	logger.Debug("response finalized")
+
 	return nil
 }
 

modules/caddyhttp/reverseproxy/streaming.go

@@ -166,12 +166,13 @@ func (h Handler) isBidirectionalStream(req *http.Request, res *http.Response) bo
 		(ae == "identity" || ae == "")
 }
 
-func (h Handler) copyResponse(dst io.Writer, src io.Reader, flushInterval time.Duration) error {
+func (h Handler) copyResponse(dst io.Writer, src io.Reader, flushInterval time.Duration, logger *zap.Logger) error {
 	if flushInterval != 0 {
 		if wf, ok := dst.(writeFlusher); ok {
 			mlw := &maxLatencyWriter{
 				dst:     wf,
 				latency: flushInterval,
+				logger:  logger.Named("max_latency_writer"),
 			}
 			defer mlw.stop()
 
@@ -185,19 +186,22 @@ func (h Handler) copyResponse(dst io.Writer, src io.Reader, flushInterval time.D
 
 	buf := streamingBufPool.Get().(*[]byte)
 	defer streamingBufPool.Put(buf)
-	_, err := h.copyBuffer(dst, src, *buf)
+	_, err := h.copyBuffer(dst, src, *buf, logger)
 	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
@@ -209,10 +213,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, werr
 			}
@@ -295,17 +304,21 @@ 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")
 		m.dst.Flush()
 		return
 	}
 	if m.flushPending {
+		m.logger.Debug("delayed flush already pending")
 		return
 	}
 	if m.t == nil {
@@ -313,6 +326,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
 }
@@ -321,8 +335,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")
 	m.dst.Flush()
 	m.flushPending = false
 }

modules/caddyhttp/reverseproxy/streaming_test.go

@@ -4,6 +4,8 @@ import (
 	"bytes"
 	"strings"
 	"testing"
+
+	"github.com/caddyserver/caddy/v2"
 )
 
 func TestHandlerCopyResponse(t *testing.T) {
@@ -18,7 +20,7 @@ func TestHandlerCopyResponse(t *testing.T) {
 	for _, d := range testdata {
 		src := bytes.NewBuffer([]byte(d))
 		dst.Reset()
-		err := h.copyResponse(dst, src, 0)
+		err := h.copyResponse(dst, src, 0, caddy.Log())
 		if err != nil {
 			t.Errorf("failed with error: %v", err)
 		}

modules/caddyhttp/server.go

@@ -669,6 +669,9 @@ func (s *Server) protocol(proto string) bool {
 // EXPERIMENTAL: Subject to change or removal.
 func (s *Server) Listeners() []net.Listener { return s.listeners }
 
+// Name returns the server's name.
+func (s *Server) Name() string { return s.name }
+
 // PrepareRequest fills the request r for use in a Caddy HTTP handler chain. w and s can
 // be nil, but the handlers will lose response placeholders and access to the server.
 func PrepareRequest(r *http.Request, repl *caddy.Replacer, w http.ResponseWriter, s *Server) *http.Request {

modules/caddyhttp/templates/templates.go

@@ -268,6 +268,7 @@ func init() {
 // {{humanize "time" "Fri, 05 May 2022 15:04:05 +0200"}}
 // {{humanize "time:2006-Jan-02" "2022-May-05"}}
 // ```
+
 type Templates struct {
 	// The root path from which to load files. Required if template functions
 	// accessing the file system are used (such as include). Default is