Summary
We have found an issue where Caddy is using the wrong connection when a handler has both forward_auth and reverse_proxy. Occasionally users were mentioning requests returning with 404 for not apparent reason. Unfortunately enabling detailed Caddy logs did not help as these were not correct, insisting their upstreams were returning 404 for endpoints which are known to exist. Only tcpdump showed the real issue; the request meant for the forward_auth endpoint was being sent on the wrong connection which did not have the expected endpoints and thus replied with 404.
For our setup we have downgraded to 2.10.2 which is not affected.
Details
Commit 8aca108 seems to be the cause as the parent 156ce99 does not exhibit this behavior.
PoC
The issue only happened sporadically and seemingly also fixed itself sometimes when connections were likely closed. To reproduce reliably we need to make the race condition window larger by adding a sleep. We can apply it to both commits to confirm it is not the source of any issue:
For 8aca108 (to make the race more likely):
diff --git a/modules/caddyhttp/reverseproxy/httptransport.go b/modules/caddyhttp/reverseproxy/httptransport.go
index 0c4d26ee..428589c5 100644
--- a/modules/caddyhttp/reverseproxy/httptransport.go
+++ b/modules/caddyhttp/reverseproxy/httptransport.go
@@ -268,6 +268,7 @@ func (h *HTTPTransport) NewTransport(caddyCtx caddy.Context) (*http.Transport, e
}
dialContext := func(ctx context.Context, network, address string) (net.Conn, error) {
+ time.Sleep(2 * time.Millisecond) // make race more likely
// The network is usually tcp, and the address is the host in http.Request.URL.Host
// and that's been overwritten in directRequest
// However, if proxy is used according to http.ProxyFromEnvironment or proxy providers,
For 156ce99 (where it will NOT cause issues):
diff --git a/modules/caddyhttp/reverseproxy/httptransport.go b/modules/caddyhttp/reverseproxy/httptransport.go
index 3031bda4..ba05d20f 100644
--- a/modules/caddyhttp/reverseproxy/httptransport.go
+++ b/modules/caddyhttp/reverseproxy/httptransport.go
@@ -267,6 +267,7 @@ func (h *HTTPTransport) NewTransport(caddyCtx caddy.Context) (*http.Transport, e
}
dialContext := func(ctx context.Context, network, address string) (net.Conn, error) {
+ time.Sleep(2 * time.Millisecond) // make race more likely
// For unix socket upstreams, we need to recover the dial info from
// the request's context, because the Host on the request's URL
// will have been modified by directing the request, overwriting
Now, to reproduce we use this Caddyfile:
{
auto_https disable_redirects
admin off
log default {
level ERROR
}
}
:18888 {
@svc path /svc/*
handle @svc {
forward_auth localhost:16060 {
uri /verify?id=x&sig=y
transport http {
keepalive_idle_conns_per_host 1000
}
}
uri strip_prefix /svc
reverse_proxy localhost:18080 {
transport http {
keepalive_idle_conns_per_host 1000
}
}
}
handle {
respond "not found" 404
}
}
And then we have a program which causes it to happen:
- Listens on the expected
forward_auth endpoint
- Listens on the expected
reverse_proxy endpoint, counting if it receives a /verify (which it definitely should not)
- Requests
/svc/ping from Caddy which we expect to hit the forward_auth with a /verify and then the reverse_proxy with a /ping
package main
import (
"context"
"io"
"log/slog"
"net/http"
"os"
"os/signal"
"sync"
"sync/atomic"
"time"
)
const (
authAddr = "127.0.0.1:16060" // auth upstream listener
svcAddr = "127.0.0.1:18080" // service upstream listener
target = "http://127.0.0.1:18888/svc/ping" // target URL (through Caddy)
workers = 300 // concurrent load workers
dur = 30 * time.Second // load duration
)
func main() {
var bugged, authHits, svcHits atomic.Int64
// mux with expeced verify endpoint
authMux := http.NewServeMux()
authMux.HandleFunc("/verify", func(w http.ResponseWriter, r *http.Request) {
authHits.Add(1)
w.WriteHeader(200)
})
// mux with unexpected verify endpoint (should never be hit)
svcMux := http.NewServeMux()
svcMux.HandleFunc("/verify", func(w http.ResponseWriter, r *http.Request) {
svcHits.Add(1)
n := bugged.Add(1)
slog.Warn("BUG TRIGGERED",
slog.Int64("count", n),
slog.String("method", r.Method),
slog.String("url", r.URL.String()),
slog.String("remote", r.RemoteAddr))
// this should not exist, so return 404 to make it obvious in the report
w.WriteHeader(404)
})
// and real endpoint we actually want to hit
svcMux.HandleFunc("/ping", func(w http.ResponseWriter, r *http.Request) {
svcHits.Add(1)
w.WriteHeader(200)
})
go func() {
if err := http.ListenAndServe(authAddr, authMux); err != nil {
slog.Error("auth upstream failed", slog.String("addr", authAddr), slog.Any("err", err))
os.Exit(1)
}
}()
go func() {
if err := http.ListenAndServe(svcAddr, svcMux); err != nil {
slog.Error("svc upstream failed", slog.String("addr", svcAddr), slog.Any("err", err))
os.Exit(1)
}
}()
// just wait for internal servers to be ready
time.Sleep(time.Second)
slog.Info("upstreams up", slog.String("auth", authAddr), slog.String("svc", svcAddr))
client := &http.Client{Transport: &http.Transport{MaxIdleConnsPerHost: 100}}
ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt)
defer stop()
ctx, cancel := context.WithTimeout(ctx, dur)
defer cancel()
var codes [600]atomic.Int64
var errs, total atomic.Int64
var wg sync.WaitGroup
slog.Info("load starting", slog.Int("workers", workers), slog.Duration("duration", dur), slog.String("target", target))
start := time.Now()
for range workers {
wg.Add(1)
go func() {
defer wg.Done()
for {
select {
case <-ctx.Done():
return
default:
}
total.Add(1)
resp, err := client.Get(target)
if err != nil {
errs.Add(1)
continue
}
io.Copy(io.Discard, resp.Body)
resp.Body.Close()
if resp.StatusCode < 600 {
codes[resp.StatusCode].Add(1)
}
}
}()
}
wg.Wait()
elapsed := time.Since(start)
if ctx.Err() == context.Canceled {
slog.Info("interrupted; printing report", slog.Duration("elapsed", elapsed.Round(time.Millisecond)))
}
for i := range codes {
if v := codes[i].Load(); v > 0 {
slog.Info("status count", slog.Int("status", i), slog.Int64("count", v))
}
}
slog.Info("load complete",
slog.Int64("errors", errs.Load()),
slog.Int64("total", total.Load()),
slog.Float64("req_per_s", float64(total.Load())/elapsed.Seconds()),
slog.Duration("elapsed", elapsed.Round(time.Millisecond)))
slog.Info("counters",
slog.Int64("bugged", bugged.Load()),
slog.Int64("auth_hits", authHits.Load()),
slog.Int64("svc_hits", svcHits.Load()))
if bugged.Load() > 0 {
slog.Error("RESULT: BUG REPRODUCED", slog.Int64("bugged", bugged.Load()))
} else {
slog.Info("RESULT: clean (no bug observed)")
}
}
Impact
This seems pretty severe, it randomly breaks the forward_auth behavior depending on timing. You could pass a foward_auth check unexpectedly if the raced connection happens to have the same endpoints and replies with 200 OK. It also breaks functionality by causing unexpected 404 responses making the handler unreliable.
AI Usage
I didn't seen this as part of the template but I can see it in your regular issues, so I added something here. I can say that we used AI to help us find the exact commit this was triggering from and also used it to help us build a simple reproducible example. I can also say that this report was written entirely by a human and AI was not involved in that part. I hope that pointing out the exact commit this was introduced in helps to fix the issue.
Summary
We have found an issue where Caddy is using the wrong connection when a handler has both
forward_authandreverse_proxy. Occasionally users were mentioning requests returning with 404 for not apparent reason. Unfortunately enabling detailed Caddy logs did not help as these were not correct, insisting their upstreams were returning 404 for endpoints which are known to exist. Onlytcpdumpshowed the real issue; the request meant for theforward_authendpoint was being sent on the wrong connection which did not have the expected endpoints and thus replied with 404.For our setup we have downgraded to 2.10.2 which is not affected.
Details
Commit 8aca108 seems to be the cause as the parent 156ce99 does not exhibit this behavior.
PoC
The issue only happened sporadically and seemingly also fixed itself sometimes when connections were likely closed. To reproduce reliably we need to make the race condition window larger by adding a sleep. We can apply it to both commits to confirm it is not the source of any issue:
For 8aca108 (to make the race more likely):
For 156ce99 (where it will NOT cause issues):
Now, to reproduce we use this Caddyfile:
{ auto_https disable_redirects admin off log default { level ERROR } } :18888 { @svc path /svc/* handle @svc { forward_auth localhost:16060 { uri /verify?id=x&sig=y transport http { keepalive_idle_conns_per_host 1000 } } uri strip_prefix /svc reverse_proxy localhost:18080 { transport http { keepalive_idle_conns_per_host 1000 } } } handle { respond "not found" 404 } }And then we have a program which causes it to happen:
forward_authendpointreverse_proxyendpoint, counting if it receives a/verify(which it definitely should not)/svc/pingfrom Caddy which we expect to hit theforward_authwith a/verifyand then thereverse_proxywith a/pingImpact
This seems pretty severe, it randomly breaks the
forward_authbehavior depending on timing. You could pass afoward_authcheck unexpectedly if the raced connection happens to have the same endpoints and replies with 200 OK. It also breaks functionality by causing unexpected 404 responses making the handler unreliable.AI Usage
I didn't seen this as part of the template but I can see it in your regular issues, so I added something here. I can say that we used AI to help us find the exact commit this was triggering from and also used it to help us build a simple reproducible example. I can also say that this report was written entirely by a human and AI was not involved in that part. I hope that pointing out the exact commit this was introduced in helps to fix the issue.