From 84ed794f5c6248f1795f608aa6fbe0710ab1ea4d Mon Sep 17 00:00:00 2001 From: Stefan Wasilewski Date: Sat, 1 Aug 2026 05:26:44 +0400 Subject: [PATCH] more rst fixes --- README.md | 19 +++++++++----- main.go | 40 ++++++++++++++++++++++------- main_test.go | 71 +++++++++++++++++++++++++++++++++++++++++----------- 3 files changed, 100 insertions(+), 30 deletions(-) diff --git a/README.md b/README.md index 3ff76f9..ce447fa 100644 --- a/README.md +++ b/README.md @@ -60,7 +60,8 @@ go build -o /usr/local/bin/tsproxy . | `--dir` | | `~/.config/tsproxy/` | State directory (node identity, keys). | | `--verbose` | `-v` | `false` | Verbose tsnet logging. | | `--probe-interval` | | `5s` | How often a *down* target is re-probed. No probing happens while it is up. | -| `--probe-timeout` | | `3s` | How long a probe or a forwarded dial may take before it counts as failed. | +| `--probe-timeout` | | `10s` | How long a reachability probe may take before the target counts as down. | +| `--dial-timeout` | | `30s` | How long a forwarded connection may take to reach the target before it is failed. | | `--idle-timeout` | | `5m` | Close a forwarded connection after this long with no traffic either way (`0` disables). | | `--trace` | | `false` | Log every accept, dial, probe and teardown, for diagnosing stalls. | @@ -115,11 +116,17 @@ plist, then remove it once the state directory has been populated. one-off failure against a healthy target costs a few milliseconds of refusal, not a whole interval. Other live connections are left alone — one failure stops new work but isn't enough to declare the target dead. -- **Dials are bounded by `--probe-timeout`.** A tailnet peer that is routable - but dead neither accepts nor refuses, so an unbounded dial parks forever - holding a local socket that nothing can reclaim: the probe loop only tears - down live connections when a probe *fails*, and a recovering target makes the - probe succeed. Forwarded connections use the same timeout as probes. +- **Dials are bounded, but generously.** A tailnet peer that is routable but + dead neither accepts nor refuses, so an unbounded dial parks forever holding + a local socket that nothing can reclaim. Forwarded dials are therefore capped + at `--dial-timeout`, which is deliberately much larger than `--probe-timeout`: + a probe is a health check that costs nothing to retry and can afford to be + impatient, while a forwarded dial has a client waiting on it and would rather + wait than fail. Tailnet dial latency is very uneven — tens of milliseconds on + a warm path, seconds when the path has to be renegotiated or fall back to + DERP — so a probe-sized budget here fails connections to a healthy target. + A dial taking more than a quarter of its budget is logged without `--trace`, + since that is the shape of trouble before it becomes a failure. - **Target loss drops live connections.** A tailnet peer can vanish without the userspace TCP stack ever erroring on an established connection, which leaves local sockets hanging and apps waiting on a dead link. Two things catch this. diff --git a/main.go b/main.go index 3175b63..e057b98 100644 --- a/main.go +++ b/main.go @@ -55,8 +55,10 @@ func main() { verbose = flag.BoolP("verbose", "v", false, "verbose tsnet logging") interval = flag.Duration("probe-interval", 5*time.Second, "how often to re-probe a target that is down (a target that is up is never probed)") - timeout = flag.Duration("probe-timeout", 3*time.Second, - "how long a probe or a forwarded dial may take before it counts as failed") + timeout = flag.Duration("probe-timeout", 10*time.Second, + "how long a reachability probe may take before the target counts as down") + dialTimeout = flag.Duration("dial-timeout", 30*time.Second, + "how long a forwarded connection may take to reach the target before it is failed") trace = flag.Bool("trace", false, "log every accept, dial, probe and teardown (for diagnosing stalls)") idle = flag.Duration("idle-timeout", 5*time.Minute, @@ -77,6 +79,9 @@ func main() { if *timeout <= 0 { log.Fatal("--probe-timeout must be positive") } + if *dialTimeout <= 0 { + log.Fatal("--dial-timeout must be positive") + } if *idle < 0 { log.Fatal("--idle-timeout must not be negative (0 disables)") } @@ -131,6 +136,7 @@ func main() { conns: make(map[net.Conn]struct{}), trace: *trace, idle: *idle, + dialWait: *dialTimeout, } log.Printf("tsproxy: %s -> %s (via tailnet as %q)", f.local, f.target, *hostname) wg.Add(1) @@ -164,7 +170,8 @@ type proxy struct { local string target string interval time.Duration - timeout time.Duration + timeout time.Duration // budget for a reachability probe + dialWait time.Duration // budget for a forwarded connection to reach the target idle time.Duration // tear down a connection after this long with no traffic; 0 disables recheck chan struct{} // nudges the probe loop to re-probe immediately trace bool // log every accept, dial, probe and teardown @@ -341,14 +348,16 @@ func (p *proxy) suspend() { p.state = stateDown p.mu.Unlock() - if ln != nil { - ln.Close() - } + // Log before closing: closing wakes the accept loop, whose own trace line + // would otherwise print first and read as if it caused this. if was == stateUp { p.logf("PORT CLOSED: a connection to the target failed, refusing connections pending probe") } else { p.tracef("suspend: port was already closed") } + if ln != nil { + ln.Close() + } p.nudge() } @@ -538,9 +547,16 @@ func (p *proxy) handle(ctx context.Context, in net.Conn, id uint64) { // local socket open with no way out: the probe loop only tears down live // connections when a probe fails, and a target that recovers makes the // probe succeed. The connection would hang for good. - p.tracef("[conn %d] dialing %s (timeout %s)", id, p.target, p.timeout) + // This budget is deliberately not --probe-timeout. A probe is a health + // check that costs nothing to retry, so it can be impatient; a forwarded + // dial has a client waiting on it and would rather wait than fail. Tailnet + // dials are also wildly variable -- tens of milliseconds on a warm path, + // seconds when the path has to be renegotiated or fall back to DERP -- so + // a probe-sized budget here fails connections to a perfectly healthy + // target. + p.tracef("[conn %d] dialing %s (timeout %s)", id, p.target, p.dialWait) dialStart := time.Now() - dialCtx, cancel := context.WithTimeout(ctx, p.timeout) + dialCtx, cancel := context.WithTimeout(ctx, p.dialWait) c, err := p.dial.Dial(dialCtx, "tcp", p.target) cancel() // governs the dial only; the returned conn outlives it dialTook := time.Since(dialStart).Round(time.Millisecond) @@ -550,7 +566,13 @@ func (p *proxy) handle(ctx context.Context, in net.Conn, id uint64) { p.suspend() return } - p.tracef("[conn %d] connected to target in %s", id, dialTook) + if dialTook > p.dialWait/4 { + // Worth seeing without --trace: a dial this slow is on its way to + // becoming a failure, and says the tailnet path is being rebuilt. + p.logf("[conn %d] slow dial: connected in %s (budget %s)", id, dialTook, p.dialWait) + } else { + p.tracef("[conn %d] connected to target in %s", id, dialTook) + } out := &targetConn{Conn: c} defer c.Close() diff --git a/main_test.go b/main_test.go index 7431e9b..6a61d5e 100644 --- a/main_test.go +++ b/main_test.go @@ -19,6 +19,7 @@ const ( modeUp dialMode = iota // connect to the echo server modeDown // fail immediately modeHang // block until the caller gives up, like a routable but dead peer + modeSlow // connect, but only after a delay, like a tailnet path being rebuilt ) // fakeTarget stands in for a tailnet target. Its echo server always runs; the @@ -27,7 +28,8 @@ const ( // established just sit there with no error from the userspace TCP stack. type fakeTarget struct { ln net.Listener - dials atomic.Int64 // every dial, probe or forwarded alike + dials atomic.Int64 // every dial, probe or forwarded alike + delay time.Duration // how long modeSlow takes to connect mu sync.Mutex mode dialMode @@ -113,6 +115,12 @@ func (f *fakeTarget) Dial(ctx context.Context, network, addr string) (net.Conn, case modeHang: <-ctx.Done() return nil, ctx.Err() + case modeSlow: + select { + case <-ctx.Done(): + return nil, ctx.Err() + case <-time.After(f.delay): + } } var d net.Dialer return d.DialContext(ctx, network, f.ln.Addr().String()) @@ -363,19 +371,7 @@ func TestTargetHardCloseIsNoticedImmediately(t *testing.T) { local := freePort(t) // Probe interval far longer than the assertion window, so a pass // can only mean the per-connection path noticed. - p := &proxy{ - dial: ft, - local: local, - target: "target:1234", - interval: 30 * time.Second, - timeout: time.Second, - recheck: make(chan struct{}, 1), - conns: make(map[net.Conn]struct{}), - } - ctx, cancel := context.WithCancel(context.Background()) - done := make(chan struct{}) - go func() { defer close(done); p.run(ctx) }() - defer func() { cancel(); <-done }() + startProxyWith(t, ft, local, 30*time.Second, time.Second, 0) waitFor(t, "local port to accept", func() bool { return !localPortRefused(local) }) @@ -416,13 +412,19 @@ func TestTargetHardCloseIsNoticedImmediately(t *testing.T) { // startProxyWith runs a proxy with explicit timings, for tests that need the // probe loop held back so a pass can only come from the connection path. func startProxyWith(t *testing.T, ft *fakeTarget, local string, interval, timeout, idle time.Duration) *proxy { + t.Helper() + return startProxyTimeouts(t, ft, local, interval, timeout, timeout, idle) +} + +func startProxyTimeouts(t *testing.T, ft *fakeTarget, local string, interval, probeTimeout, dialTimeout, idle time.Duration) *proxy { t.Helper() p := &proxy{ dial: ft, local: local, target: "target:1234", interval: interval, - timeout: timeout, + timeout: probeTimeout, + dialWait: dialTimeout, idle: idle, recheck: make(chan struct{}, 1), conns: make(map[net.Conn]struct{}), @@ -547,3 +549,42 @@ func TestPortReturnsAfterTransientFailure(t *testing.T) { return !localPortRefused(local) }) } + +// A tailnet dial is tens of milliseconds on a warm path and seconds when the +// path has to be renegotiated. Forwarded connections must be given their own, +// far more generous budget than a reachability probe -- reusing the probe +// budget fails connections to a target that is perfectly healthy, which the +// probe issued moments later then confirms. +func TestSlowDialSucceedsWithinItsOwnBudget(t *testing.T) { + ft := newFakeTarget(t) + ft.delay = 400 * time.Millisecond + local := freePort(t) + // Probe budget far below the dial delay; dial budget comfortably above it. + p := startProxyTimeouts(t, ft, local, 30*time.Second, + 100*time.Millisecond, 3*time.Second, 0) + waitFor(t, "local port to accept", func() bool { return !localPortRefused(local) }) + + ft.setMode(modeSlow) + + c, err := net.Dial("tcp", local) + if err != nil { + t.Fatalf("dial local: %v", err) + } + defer c.Close() + if _, err := c.Write([]byte("ping")); err != nil { + t.Fatalf("write: %v", err) + } + buf := make([]byte, 4) + c.SetReadDeadline(time.Now().Add(5 * time.Second)) + if _, err := io.ReadFull(c, buf); err != nil { + t.Fatalf("slow dial (%s) was failed despite a %s budget: %v", ft.delay, p.dialWait, err) + } + if string(buf) != "ping" { + t.Fatalf("echo = %q, want %q", buf, "ping") + } + + // And a slow-but-successful dial must not have taken the port down. + if localPortRefused(local) { + t.Error("port closed after a slow but successful dial") + } +}