more rst fixes

README.md

@@ -60,7 +60,8 @@ go build -o /usr/local/bin/tsproxy .
 | `--dir`     |      | `~/.config/tsproxy/<name>` | 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
+- **Dials are bounded, but generously.** A tailnet peer that is routable but
-  but dead neither accepts nor refuses, so an unbounded dial parks forever
+  dead neither accepts nor refuses, so an unbounded dial parks forever holding
-  holding a local socket that nothing can reclaim: the probe loop only tears
+  a local socket that nothing can reclaim. Forwarded dials are therefore capped
-  down live connections when a probe *fails*, and a recovering target makes the
+  at `--dial-timeout`, which is deliberately much larger than `--probe-timeout`:
-  probe succeed. Forwarded connections use the same timeout as probes.
+  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.

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,
+		timeout = flag.Duration("probe-timeout", 10*time.Second,
-			"how long a probe or a forwarded dial may take before it counts as failed")
+			"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 {
+	// Log before closing: closing wakes the accept loop, whose own trace line
-		ln.Close()
+	// 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()
 

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{
+			startProxyWith(t, ft, local, 30*time.Second, time.Second, 0)
-				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 }()
 
 			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")
+	}
+}