eli/vpsetup
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity
Files
main
vpsetup/docs/research/caddy-grpc-upstream-h2.md
T

35 KiB
Raw Permalink Blame History

Caddy v2.11.4 上游 gRPC/h2 长流行为：源码级调研报告

来源：2026-10-11 由研究代理产出（克隆 caddyserver/caddy@v2.11.4 + Go 1.25.1 h2_bundle.go + GitHub issues/PR + 官方文档），原文存于当时的 /tmp。 结论摘要与决策要点见 docs/HANDOFF.md §11 / §11.1；本文件保留完整引用与逐行证据。

Scope: Caddy v2.11.4 (tag e2eee6a7fce366321294c9c2a79f3146891dcbdf, go.mod go 1.25.1), Go 1.25.x net/http + bundled golang.org/x/net/http2, Traefik v3.x. Primary sources only. Anything not provable from a source I actually read is marked UNCONFIRMED.

Local verification material (read-only, under /tmp): /tmp/caddy-grpc-research/caddy-src/ (git clone, tags v2.11.4 + master), /tmp/caddy-grpc-research/h2_bundle_125.go (Go 1.25.1 src/net/http/h2_bundle.go), /tmp/caddy-grpc-research/h2server.go (x/net/http2 server.go, master), /tmp/caddy-grpc-research/ht_v2114.go, /tmp/caddy-grpc-research/cf_v2114.go (v2.11.4 transports).

1. How reverse_proxy handles gRPC specifically — it does not

Finding 1.1 — there is no gRPC code in reverse_proxy at all. git grep -n "grpc" v2.11.4 -- '*.go' over the whole Caddy repo returns only three files, and none is the proxy: modules/caddyhttp/matchers.go (the protocol grpc request matcher), modules/caddyhttp/celmatcher_test.go, modules/caddyhttp/reverseproxy/addresses_test.go (a unix+h2c//var/grpc.sock address example). The matcher is the only gRPC-aware code:

// modules/caddyhttp/matchers.go:1370 (v2.11.4)
case "grpc":
    return strings.HasPrefix(r.Header.Get("Content-Type"), "application/grpc"), nil

Maintainer confirmation (Caddy forum, Francis Lavoie, Mar 2021 — link):

"Where are you seeing support for this? I don't think reverse_proxy directly supports grpc://. I don't see anything in the codebase for this. The protocol matcher does support grpc, but that's totally separate from reverse_proxy."

Finding 1.2 — buffering/timeouts are switched off generically, not by Content-Type. flushInterval() in modules/caddyhttp/reverseproxy/streaming.go (v2.11.4):

func (h Handler) flushInterval(req *http.Request, res *http.Response) time.Duration {
	resCTHeader := res.Header.Get("Content-Type")
	resCT, _, err := mime.ParseMediaType(resCTHeader)
	// For Server-Sent Events responses, flush immediately.
	if err == nil && resCT == "text/event-stream" { return -1 }
	// We might have the case of streaming for which Content-Length might be unset.
	if res.ContentLength == -1 { return -1 }
	// for h2 and h2c upstream streaming data to client (issues #3556 and #3606)
	if h.isBidirectionalStream(req, res) { return -1 }
	return time.Duration(h.FlushInterval)
}

The Handler field comment is explicit:

FlushInterval caddy.Duration — "This option is ignored when the upstream's response is recognized as a streaming response, or if its content length is -1; for such responses, writes are flushed to the client immediately." — modules/caddyhttp/reverseproxy/reverseproxy.go:139

The docs say the same (reverse_proxy → Streaming):

"flush_interval … A negative value (typically -1) suggests 'low-latency mode' … This option is ignored and responses are flushed immediately to the client if one of the following applies from the response: Content-Type: text/event-stream; Incremental: ?1; Content-Length is unknown; HTTP/2 on both sides of the proxy, Content-Length is unknown, and Accept-Encoding is either not set or is 'identity'."

"By default, the proxy partially buffers the response for wire efficiency."

Conclusion for Q1: gRPC responses carry no Content-Length (they are DATA + trailers), so Caddy already flushes every write immediately. flush_interval -1 is NOT required for server-streaming gRPC — it is a no-op for that case (harmless as belt-and-braces, but it will not fix anything). This matches the historical thread where Matt Holt asked "What happens if you set flush_interval -1 explicitly?" and the reporter answered "No change, unfortunately."

Two residual caveats:

  • request_buffers defaults to 0 (no request buffering), so gRPC request bodies stream through — do not set it.
  • Bidirectional/interleaved gRPC was genuinely broken in 2021 (that same thread: "it appears it doesn't handle a client trying to read the server metadata … before sending its request"); those threads were closed as Caddy moved on. By v2.11.4 the code explicitly names gRPC as a supported bi-directional case (PR #7719 body, below), so that old limitation should not be assumed. UNCONFIRMED that any interleaving limitation remains in v2.11.4 — I found no open issue for it.

2. Upstream HTTP/2 keepalive semantics, and stale pooled connections

2.1 What the transport http options actually do (v2.11.4)

Verified in modules/caddyhttp/reverseproxy/caddyfile.go:1255-1310 and httptransport.go:212-216, 477-495:

Caddyfile key Go field What it really is
keepalive <dur> / off KeepAlive.IdleConnTimeout → http.Transport.IdleConnTimeout How long an idle connection is kept in the pool. Default 2m. Not "keep the connection alive for ever".
keepalive_interval <dur> KeepAlive.ProbeInterval → net.Dialer.KeepAlive + net.KeepAliveConfig{Enable, Interval} TCP keepalive probes only. Default 30s. It is not an HTTP/2 PING.
keepalive_idle_conns <n> MaxIdleConns Default 0 = no limit
keepalive_idle_conns_per_host <n> MaxIdleConnsPerHost Default 32

Struct docs, verbatim (httptransport.go):

// Whether HTTP Keep-Alive is enabled. Default: `true`
Enabled *bool `json:"enabled,omitempty"`
// How often to probe for liveness. Default: `30s`.
ProbeInterval caddy.Duration `json:"probe_interval,omitempty"`
// How long connections should be kept alive when idle. Default: `2m`.
IdleConnTimeout caddy.Duration `json:"idle_timeout,omitempty"`

dialer.KeepAlive = time.Duration(h.KeepAlive.ProbeInterval)
dialer.KeepAliveConfig = net.KeepAliveConfig{
    Enable:   h.KeepAlive.ProbeInterval > 0,
    Interval: time.Duration(h.KeepAlive.ProbeInterval),
}
rt.IdleConnTimeout = time.Duration(h.KeepAlive.IdleConnTimeout)

keepalive_idle_timeout and keepalive_probe_interval do not exist in transport http. The parser accepts only keepalive, keepalive_interval, keepalive_idle_conns, keepalive_idle_conns_per_host. (keepalive_idle / keepalive_count do exist — but as global server options on the listener side: servers { keepalive_interval … keepalive_idle … keepalive_count … }, added in PR #7298. That is a likely source of the naming confusion.)

Finding 2.2 (important, and counter-intuitive): Caddy configures no HTTP/2 PING health check on upstreams. git grep -n "ReadIdleTimeout\|PingTimeout\|WriteByteTimeout" v2.11.4 -- '*.go' → zero matches. Go's http2Transport reads those from configFromTransport (readIdleTimeout: conf.SendPingTimeout, pingTimeout: conf.PingTimeout — h2_bundle_125.go:8117), and Caddy never sets them, so ReadIdleTimeout = 0 = no health-check PING. keepalive_interval 15s therefore does not keep the upstream h2 connection warm and does not detect a half-open h2 connection. (Corroborating issue history: #7144 "Keep-alive interval may be set incorrectly" → #7151 "Use KeepAliveConfig to pass keepalive_interval to listener's accepted sockets".)

2.3 Does a request fail fast on a stale pooled h2 connection? Sometimes — and that is the crux.

From Go 1.25.1 src/net/http/h2_bundle.go (verbatim):

func http2shouldRetryRequest(req *Request, err error) (*Request, error) {
	if !http2canRetryError(err) { return nil, err }
	// If the Body is nil (or http.NoBody), it's safe to reuse this request and its Body.
	if req.Body == nil || req.Body == NoBody { return req, nil }
	// If the request body can be reset back to its original state via req.GetBody, do that.
	if req.GetBody != nil { ... }
	// The Request.Body can't reset back to the beginning, but we don't seem to have
	// started to read from it yet, so reuse the request directly.
	if err == http2errClientConnUnusable { return req, nil }
	return nil, fmt.Errorf("http2: Transport: cannot retry err [%v] after Request.Body was written; define Request.GetBody to avoid this error", err)
}

func http2canRetryError(err error) bool {
	if err == http2errClientConnUnusable || err == http2errClientConnGotGoAway { return true }
	if se, ok := err.(http2StreamError); ok {
		if se.Code == http2ErrCodeProtocol && se.Cause == http2errFromPeer { return true }
		return se.Code == http2ErrCodeRefusedStream
	}
	return false
}
  • errClientConnUnusable — "http2: client conn not usable" — is raised when the pooled conn already fails canTakeNewRequestLocked (goAway != nil || closed || closing || doNotReuse || tooIdleLocked() || at MAX_CONCURRENT_STREAMS). This is retried transparently, even for a non-resettable body.
  • errClientConnGotGoAway — "http2: Transport received Server's graceful shutdown GOAWAY" — this is what setGoAway assigns to streams already in flight whose ID > LastStreamID: cs.abortStreamLocked(http2errClientConnGotGoAway) with the comment "Aborting the stream with errClentConnGotGoAway indicates that the request should be retried on a new connection." But the retry is then blocked by the body check above.
  • ErrCodeRefusedStream likewise passes canRetryError but is then blocked by the body check.
  • errClientConnNotEstablished (first request on a brand-new conn that died) "aborts the retry loop" fatally.

And Caddy never sets GetBody: git grep -n GetBody v2.11.4 -- modules/caddyhttp/ returns nothing. Caddy's cloned upstream request is built from the inbound *http.Request, whose GetBody is nil for an inbound gRPC POST.

⇒ A GOAWAY (or a REFUSED_STREAM reset) that lands on a gRPC POST whose body is not resettable produces an immediate upstream round-trip error, which statusError() turns into 502 Bad Gateway. A merely idle/closed pooled connection does not — it is silently retried on a fresh connection.

Issue-tracker status of this race: I found no Caddy issue dedicated to "stale pooled h2 conn → 502" (UNCONFIRMED that one exists). The nearest open reports are:

3. Candidates that can kill a stream ~200 ms after it opens, and how to tell them apart

3.0 First, why the client sees two different errors — this is diagnostic gold.

reverseproxy.go:1278-1286 (v2.11.4):

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;
    // we'll just log the error and abort the stream here and panic just as
    // the standard lib's proxy to propagate the stream error.
    // see issue https://github.com/caddyserver/caddy/issues/5951
    if c := logger.Check(zapcore.WarnLevel, "aborting with incomplete response"); c != nil {
        c.Write(zap.Error(err))
    }
    panic(http.ErrAbortHandler)
}

Go's h2 server turns a handler panic into a stream reset (h2server.go:2329, write: handlerPanicRST{rw.rws.stream.id}) and stays silent for ErrAbortHandler (if e != nil && e != http.ErrAbortHandler { … sc.logf("http2: panic serving …") }).

⇒ Same upstream failure, two client-visible faces depending on timing:

  • failure before rw.WriteHeader(res.StatusCode) → Caddy 502 → gRPC Unavailable: unexpected HTTP status code received;
  • failure after headers were copied but mid-body → ErrAbortHandler → RST_STREAM → gRPC Internal: stream terminated by RST_STREAM.

Seeing both messages alternating is exactly what an upstream-side failure race looks like; it is not evidence of two different bugs.

# Candidate Verdict for this deployment How to distinguish
3.1 flush_interval response buffering Ruled out. §1.2: unknown Content-Length ⇒ already flushed immediately. Add flush_interval -1; if nothing changes, as documented.
3.2 MAX_CONCURRENT_STREAMS mismatch Ruled out as a fast-failure. Go's h2 client does not fail — it waits on a cond var: awaitOpenSlotForStreamLocked loops cc.cond.Wait() until currentRequestCountLocked() < maxConcurrentStreams. Go's h2 server RSTs excess streams: return sc.countError("over_max_streams", streamError(id, ErrCodeProtocol)) / ("over_max_streams_race", streamError(id, ErrCodeRefusedStream)) (h2server.go:1922-1936) — it does not GOAWAY. Symptom would be latency/queueing, not fast errors. But note the tail: an RST(REFUSED_STREAM) landing on a non-resettable body ⇒ §2.3 ⇒ 502. Traefik default http2.maxConcurrentStreams = 250 (docs table below).
3.3 Stale pooled connection Leading candidate. Closed-idle conn → silently retried; GOAWAY / REFUSED_STREAM on an in-flight gRPC POST → instant 502 because Caddy sets no GetBody (§2.3). DEBUG log "upstream roundtrip" with error — the error string is decisive (… graceful shutdown GOAWAY, … cannot retry err […] after Request.Body was written, http2: client conn not usable, http2: client conn could not be established). Then ss -tin dst :10443 / tcpdump: a fresh TLS handshake per failure ⇒ pooled-conn churn; a single long-lived conn ⇒ not this.
3.4 Host / :authority mismatch Unlikely here but cheap to rule out. header_up Host really does rewrite :authority — modules/caddyhttp/headers/headers.go:349-374 pulls r.Host into r.Header["Host"], applies ops, then writes back r.Host = r.Header["Host"][last]. Since Caddy v2.11.0 the Host is auto-set to the upstream host for HTTPS upstreams (docs + #7565). A wrong Host yields a normal HTTP response from Traefik (404/421), not a Caddy-generated 502: access-log status = the upstream's status, resp_headers show Traefik's, and there is no http.handlers.reverse_proxy WARN/ERROR. Traefik's own access log shows the :authority it received.
3.5 v2.11.4 regression in bodyNopCloserIfNotRead Real, version-exact, but produces a HANG not a fast error. PR #7719 ("first released in v2.11.4") introduced bodyNopCloserIfNotRead; its own PR body says the previous io.NopCloser approach "would make transport unable to close the body in legitimate cases such as bi-directional streaming, i.e. grpc and extended websockets over h2/h3". #8185: "The bodyNopCloserIfNotRead wrapper does not close the underlying request body in its Close method while its Read method is waiting to receive the first byte, even after the HTTP/2 transport has asked to close it (following an RST_STREAM signal received from the upstream). As a result, the blocked Read never returns, and the request hangs." Repro: "an upstream HTTP/2 server that accepts a request, waits a short time (about 300 ms), and then aborts the stream (RST_STREAM) without sending any response headers"; "the hang happened every time (8 out of 8 requests) on v2.11.4 … and never on v2.11.3." Client-side deadline exceeded / no response at all, with Caddy logging nothing, distinguishes it from §3.3's instant 502. Recommendation: do not "fix" this by upgrading blindly — v2.11.6 is the release that introduced the new 1-minute idle timeouts, see 3.6.
3.6 Caddy's own server timeouts Ruled out on v2.11.4. v2.11.4 defaults only idle 5m and read_header 1m; read_body/write are unset = no timeout (modules/caddyhttp/app.go: defaultIdleTimeout = 5 * time.Minute, defaultReadHeaderTimeout = time.Minute). But v2.11.6 changed this — release notes: "New 1-minute idle read/write timeouts by default. If a request body read or a response write stalls (makes no progress at all) for longer than that, the connection is aborted." and it regressed streaming: #8103 ("v2.11.4 … is not affected"), #8118 "write_idle (v2.11.6) causes h2 streaming responses that are idle for the specified duration to fail", #8101 panic in IdleTimeoutReader. If you upgrade past v2.11.4, pin timeouts { read_body_idle 0 write_idle 0 } (verify semantics on your version) or stay on v2.11.4.
3.7 Transport read_timeout / write_timeout Ruled out (both unset by default) but a real trap: never set them. They are enforced by wrapping the raw *net.TCPConn (tcpRWTimeoutConn.Read/Write do SetReadDeadline(now+timeout) per call) — an idle gRPC stream would be killed. httptransport.go:355-359. transport http { read_timeout … } present in the config.
3.8 Config reload Plausible and easy to miss. Cleanup() closes the handler's connections; #8143 shows module cleanup can run while requests are still active. journalctl -u caddy for reloads; correlate reload timestamps with stream deaths. stream_close_delay is the mitigation hook (it exists precisely for "avoid a thundering herd of reconnecting clients").
3.9 Traefik-side h2 / GOAWAY See §3.10. Traefik access log per hop + keepAliveMaxRequests config.

3.10 Traefik defaults (primary source: https://doc.traefik.io/traefik/routing/entrypoints/)

Option Documented default
transport.respondingTimeouts.readTimeout 60s
transport.respondingTimeouts.writeTimeout 0s (no timeout)
transport.respondingTimeouts.idleTimeout 180s
http2.maxConcurrentStreams 250
transport.keepAliveMaxRequests 0 (no limit) — "Set the maximum number of requests Traefik can handle before sending a Connection: Close header to the client (for HTTP2, Traefik sends a GOAWAY)"
transport.keepAliveMaxTime 0s (no limit) — same GOAWAY wording

Traefik→backend (https://doc.traefik.io/traefik/reference/routing-configuration/http/load-balancing/serverstransport/): forwardingTimeouts.dialTimeout 30s, responseHeaderTimeout 0s, idleConnTimeout 90s, readIdleTimeout 0s, pingTimeout 15s.

The GOAWAY chain is now provable end-to-end:

  1. Go's h2 server sends a graceful GOAWAY when it goes idle — h2server.go, verbatim: 
    case idleTimerMsg:
    sc.vlogf("connection is idle")
    sc.goAway(ErrCodeNo)
    with sc.idleTimer = time.AfterFunc(sc.srv.IdleTimeout, sc.onIdleTimer) (Traefik arms this from entryPoints.<name>.transport.respondingTimeouts.idleTimeout). Same on graceful shutdown: sc.shutdownOnce.Do(func() { sc.sendServeMsg(gracefulShutdownMsg) }) (h2server.go:1337).
  2. Caddy's pooled h2 conn receives it; setGoAway aborts in-flight streams with ID > LastStreamID using errClientConnGotGoAway.
  3. Go will not retry that on a request with a non-resettable body (§2.3) and Caddy sets no GetBody ⇒ instant 502 (or RST_STREAM if headers already went out).

The structural asymmetry to exploit: Caddy's keepalive (pool idle timeout, default 2m) and Traefik's idleTimeout (default 180s) are independent. Whichever side closes the idle h2 connection first wins the race; if Traefik closes first you get a GOAWAY into Caddy's pool. The user reports ~300 s direct, which is more than Traefik's documented 180 s default — so that value is configured, UNCONFIRMED at what. If the effective Traefik idle timeout is below 120 s, the GOAWAY window is hit while Caddy still trusts the connection.

4. Recommended Caddy config for reliably proxying long-lived gRPC to a Traefik/Go h2 origin

Diagnosis-first — apply §5 logging before changing behaviour, then:

netbird.savorcare.com {
	bind 127.0.0.1 [::1]
	tls /etc/caddy/certs/netbird/fullchain.pem /etc/caddy/certs/netbird/key.pem {
		alpn h2 http/1.1
	}

	reverse_proxy https://qhxxg.savorcare.com:10443 {
		# Host/:authority — keep, it is correct AND it is what Traefik routes on.
		header_up Host netbird.savorcare.com

		# Make Caddy drop the pooled h2 conn BEFORE the origin's idle timeout can
		# GOAWAY us. Pick ≈ half the origin's entryPoint idleTimeout.
		# Do NOT raise this above the origin's idle timeout.
		#   keepalive off  -> never reuse; maximum safety, worst latency (good A/B test)
		keepalive 60s

		# Belt-and-braces only: a no-op for gRPC (Content-Length unknown already forces
		# immediate flush). Costs nothing, removes one variable.
		flush_interval -1

		# OPTIONAL: only after you have verified the origin answers 200 for this URI
		# (see the warning below). Keeps the pooled h2 connection warm and makes
		# caddy_reverse_proxy_upstreams_healthy meaningful instead of a constant 1.
		#   health_uri /
		#   health_status 2xx
		#   health_interval 15s
		#   health_timeout 5s
		#   health_fails 3

		transport http {
			tls_server_name netbird.savorcare.com

			# "2" only enables h2; it does NOT enforce it (see below).
			versions 2

			# TCP keepalive probes. NOT an h2 PING — Caddy exposes no h2 ping option.
			keepalive_interval 15s

			# NEVER set read_timeout/write_timeout here: they wrap the raw TCPConn and
			# will kill idle streams.
			# Do not set request_buffers/response_buffers: they break streaming.
		}
	}
}

Two traps in the block above — read before copying it.

  • Active health checks are a production risk on a gRPC-only vhost. A health check is a plain GET <health_uri> that must return 200 (default health_status 200, health_fails 1) or the upstream is marked down and stops receiving traffic. Before enabling it, confirm the origin answers: curl -sS -o /dev/null -w '%{http_code}\n' --http2 -x '' --resolve netbird.savorcare.com:10443:$(dig +short qhxxg.savorcare.com|head -1) -H 'Host: netbird.savorcare.com' https://netbird.savorcare.com:10443/. If that is not a 200, either pick a URI that is, or use health_upstream + health_headers, or leave health checks off and rely on §5 logging instead.
  • stream_close_delay does NOT protect plain h2 gRPC streams. In v2.11.4 registerConnection is only called from handleUpgradeResponse (streaming.go:202-203), which is only reached on res.StatusCode == http.StatusSwitchingProtocols (reverseproxy.go:1219). A normal gRPC-over-h2 proxy never returns 101, so it is not registered and stream_close_delay is inert for it. Config-reload teardown of live h2 streams is therefore unmitigated by that directive (#8143). stream_close_delay is still worth setting if you ever proxy WebSocket/Extended CONNECT, but do not expect it to fix gRPC. versions 2 is not "h2 only". http2.ConfigureTransport(rt) appends both protocols to the ALPN list (Go 1.25.1 h2_bundle.go, inside every Caddy binary):
if !http2strSliceContains(t1.TLSClientConfig.NextProtos, "h2") {
	t1.TLSClientConfig.NextProtos = append([]string{"h2"}, t1.TLSClientConfig.NextProtos...)
}
if !http2strSliceContains(t1.TLSClientConfig.NextProtos, "http/1.1") {
	t1.TLSClientConfig.NextProtos = append(t1.TLSClientConfig.NextProtos, "http/1.1")
}

Caddy's own code only touches rt.Protocols for h2c, with the comment "Protocols field is only used when the request is not using TLS, http1/2 over TLS is still allowed" (httptransport.go, v2.11.4). So if the origin ever stops offering h2 over ALPN you silently get HTTP/1.1 to the origin — which for gRPC is fatal and for plain HTTP/2 requests is invisible. Verify the negotiated protocol on the Traefik side (§5). There is no Caddy Caddyfile knob that hard-pins h2 for a TLS upstream. UNCONFIRMED: no issue found requesting one.

lb_try_duration / lb_retries — do not enable for gRPC. Two independent reasons:

  • Docs: "lb_retry_match … A request must match this condition in order to be retried if the connection to the upstream succeeded but the subsequent round-trip failed. If the connection to the upstream failed, a retry is always allowed. By default, only GET requests are retried." — a gRPC POST is not GET, so mid-flight failures are not retried anyway; and a retry that does happen replays a body that has already been consumed.
  • Bug #8166: with a request-only lb_retry_match expression, "the request is sent again to the next upstreams (a POST arrives with an empty body after the first attempt), and once the retries run out the client gets a 502". Fixed only after v2.11.7.

Also: do not set request_buffers (it breaks incremental forwarding and, per the docs, an incremental request with an explicit buffer now gets 501 Not Implemented), and do not set read_timeout/write_timeout.

5. Diagnostics that will prove which candidate it is

5.1 Global DEBUG logging (required — the site log directive is not enough)

The log directive's level only affects access logs, and the docs state: "Note that access logs currently only emit INFO and ERROR level logs." The proxy's own DEBUG lines (e.g. "upstream roundtrip", reverseproxy.go:1057) come from the module logger http.handlers.reverse_proxy under the global logger. So:

{
	log {
		level DEBUG
		output file /var/log/caddy/caddy-debug.log
		# or: output stderr   (then: journalctl -u caddy -f -l)
	}
}

netbird.savorcare.com {
	...
	log {
		output file /var/log/caddy/netbird-access.log
		format json
	}
}

Log lines to grep for, and what each one proves:

Line (logger / level) Meaning
http.handlers.reverse_proxy DEBUG "upstream roundtrip" + error, upstream, duration, request The decisive line. reverseproxy.go:1038-1060. The error string distinguishes §3.3 (… graceful shutdown GOAWAY, … cannot retry err […] after Request.Body was written, http2: client conn not usable, http2: client conn could not be established) from §3.4 (no error at all).
http.handlers.reverse_proxy WARN "aborting with incomplete response" + error §3.0: the upstream died mid-body; Caddy then panics ErrAbortHandler → RST_STREAM → gRPC Internal. Concurrency of this with 502s proves one upstream failure, not two bugs.
http.handlers.reverse_proxy DEBUG "closed response body from upstream" body-close error surfaced
http.handlers.reverse_proxy DEBUG "wrote header", "response finalized", "retrying" ordering/timing of the failure vs. headers
http.log.error (level ERROR) with duration + error handler error path, server.go:408
access log "handled request" (INFO/ERROR) see below

Access-log fields that matter (server.go:895-905): status, duration, size, bytes_read, resp_headers, user_id, request (proto, host, uri, headers). Site-level log { level DEBUG } adds nothing.

Read it like this:

  • status: 502 + duration ≈ 0.0002 s → Caddy-side upstream failure, §3.3/§3.9. Cross-check the DEBUG error string.
  • status: 200 + small size + short duration, then the client still errors → the failure is after Caddy handed back a good response; look for WARN "aborting with incomplete response".
  • status: 200 + duration ≈ the client-reported lifetime → Caddy is not cutting the stream; the cut is on the client↔Caddy hop (or the client's own logic).
  • status: 502 + large duration → timeouts/queueing (§3.2), not a stale-conn race.

5.2 Go's own HTTP/2 trace (the only place GOAWAY/RST_STREAM frames are named)

Caddy cannot log these through its own logger. Set on the Caddy service only, temporarily:

sudo systemctl edit caddy
# [Service]
# Environment=GODEBUG=http2debug=2
sudo systemctl restart caddy && journalctl -u caddy -f

This turns on golang.org/x/net/http2 verbose logging to stderr, including the client-side "http2: Transport received GOAWAY…", RoundTrip retrying after failure: …, "http2: Transport failed to get client conn" and per-frame traces. Invaluable for §3.3/§3.9. UNCONFIRMED: I did not exercise GODEBUG=http2debug=2 against a live v2.11.4 build — verify the output appears in your version before relying on it.

5.3 Metrics — caddy_reverse_proxy_upstreams_healthy exists but will NOT answer this question

The metric is documented (caddyserver.com/docs/metrics): "A gauge of the reverse proxy upstreams healthiness. Value 0 means the upstream is unhealthy, where as 1 means the upstream is healthy." Scrape it from the admin endpoint: curl -s localhost:2019/metrics | grep caddy_reverse_proxy.

Caveat, verified in source: it is fed from Upstream.Healthy(), which is

healthy := u.healthy()
if healthy && u.healthCheckPolicy != nil { healthy = u.Host.Fails() < u.healthCheckPolicy.MaxFails }
if healthy && u.cb != nil { healthy = u.cb.OK() }

— i.e. only passive-health-check fail counts and the circuit breaker. With no health checks configured (fail_duration / health_uri) and no circuit breaker it is a constant 1. It says nothing about TCP/h2 connection-pool state, and there is no metric for pooled upstream connections in Caddy (the only other reverse-proxy metrics are stream gauges/counters: streams_active, streams_total, stream_duration_seconds, stream_bytes_total — and those cover upgraded streams, not plain h2 gRPC). Enabling health_uri (§4) is what makes the gauge meaningful.

5.4 Prove which hop and which protocol

  • Traefik access log (JSON): look for the requests arriving from Caddy. Check proto (HTTP/2.0 vs HTTP/1.1 — proves whether versions 2 really negotiated h2), RouterName, originStatus/OriginDuration, and whether the gRPC request is there at all. If failures show no Traefik-side entry while Caddy logs an "upstream roundtrip" error, the failure was pre-header on the origin connection ⇒ §3.3/§3.9.
  • Traefik's static config: entryPoints.<name>.transport.respondingTimeouts.idleTimeout (default 180s) vs Caddy's keepalive (default 120s). And confirm transport.keepAliveMaxRequests / keepAliveMaxTime are 0 — any non-zero value makes Traefik send GOAWAY by design.
  • Local socket/flow check on the Caddy host: ss -tin dst :10443 — one long-lived ESTABLISHED conn with a growing Send-Q/bytes_sent means the pool is healthy; a new local port per failure means Caddy is re-dialing every time (stale-conn churn). sudo tcpdump -ni any port 10443 -A | grep -i goaway if you want the frames.
  • A/B test that isolates §3.3 in one line: set keepalive off (never reuse the upstream connection). If the 200 ms failures vanish, it is a pooled-connection/GOAWAY problem. If they persist, it is not.
  • A/B test that isolates the origin hop: point Caddy at a local h2c echo/grpcurl target and stream for minutes. If that is stable, the Caddy side is fine and the origin hop is the problem.

6. Confidence summary

Confirmed from primary sources (docs + source I read myself): no gRPC-specific code in reverse_proxy (§1.1); flush_interval is ignored when Content-Length is unknown, so it is not needed for server-streaming gRPC (§1.2); exact meaning/defaults of keepalive/keepalive_interval/keepalive_idle_* and the absence of keepalive_idle_timeout/keepalive_probe_interval (§2.1); Caddy sets no h2 ReadIdleTimeout/PingTimeout (§2.2); Go's retry rules and Caddy's missing GetBody ⇒ GOAWAY/REFUSED_STREAM can 502 instantly (§2.3); Caddy v2.11.4 server timeout defaults and the v2.11.6 change (§3.6); the ErrAbortHandler → RST_STREAM path explaining the two client errors (§3.0); Go's h2 client queues instead of failing at MAX_CONCURRENT_STREAMS, and Go's h2 server RSTs rather than GOAWAYs on excess streams, but does GOAWAY on idle (§3.2, §3.10); all Traefik defaults in §3.10; metric semantics (§5.3).

UNCONFIRMED / not established:

  1. Which of §3.3 / §3.5 / §3.8 / §3.9 is actually firing in this deployment — no live access, and no logs supplied.
  2. Whether Traefik in this deployment has keepAliveMaxRequests / keepAliveMaxTime non-zero, or an idleTimeout below 120 s. The observed ~300 s direct lifetime does not match Traefik's documented 180 s default, so something is configured; I could not see what.
  3. Whether the h2 hop Caddy→Traefik really negotiates h2 (given §4's ALPN finding).
  4. Whether a dedicated Caddy issue exists for "stale pooled h2 conn → instant 502"; I searched and found none.
  5. That GODEBUG=http2debug=2 produces the expected output on a v2.11.4 build (documented Go facility; not exercised here).
  6. Netbird's own client-side gRPC keepalive/deadline settings — out of scope, not inspected.

7. Source index

Reference in New Issue View Git Blame Copy Permalink