urltest batch.Wait() blocks indefinitely when relay is unresponsive, stalling transparent gateway (goroutine dump attached)

[HouMinXi]

Operating system

Linux

System version

iStoreOS (OpenWrt-based) x86_64, kernel 5.15

Installation type

Original sing-box Command Line

Version

sing-box version 1.10.7

Environment: go1.23.4 linux/amd64
Tags: with_gvisor,with_quic,with_dhcp,with_wireguard,with_ech,with_utls,with_reality_server,with_acme,with_clash_api
Revision: 253b41936ecd6ae17948d49d9c510d7100830927
CGO: disabled

Description

Transparent gateway (tproxy inbound + urltest outbound with 6 relay servers) becomes unresponsive under normal residential traffic. The process stays alive but stops processing connections. accept() works at the kernel level but no data flows.

This is related to #4144 (transparent gateway stall under normal connection churn). We captured a SIGQUIT goroutine dump during a live stall, which shows the blocking point is URLTestGroup.urlTest() calling batch.Wait() with no timeout.

Evidence: goroutine dump during stall (205 goroutines)

State distribution at stall time:

  66 [IO wait]
  26 [IO wait, 1 minutes]
  18 [IO wait, 2 minutes]
  10 [IO wait, 4 minutes]
  20 [select]
  18 [select, 2 minutes]
  17 [select, 4 minutes]
  12 [select, 1 minutes]
   1 [semacquire, 3 minutes]   ← URLTest batch.Wait()

The deadlock chain:

1. URLTestGroup.urlTest() (goroutine 103) spawns batch workers to probe each outbound via batch.Go()
2. One batch worker (goroutine 381) is stuck in TCPConn.Read for 1+ minute — the relay server accepted the TCP connection but never sent an HTTP response
3. batch.Wait() (goroutine 103) blocks on sync.WaitGroup.Wait() indefinitely — one stuck worker blocks the entire batch
4. While the batch is blocked, selectedOutboundTCP/selectedOutboundUDP are never updated
5. New connections keep being routed to the unresponsive relay
6. 168 CopyConn goroutines accumulate, all blocked in IO wait on the dead relay

Goroutine 103 (the blocked URLTest checker):

goroutine 103 [semacquire, 3 minutes]:
sync.(*WaitGroup).Wait(...)
  sync/waitgroup.go:118
github.com/sagernet/sing/common/batch.(*Batch[...]).Wait(...)
  github.com/sagernet/sing@v0.5.1/common/batch/batch.go:77
github.com/sagernet/sing-box/outbound.(*URLTestGroup).urlTest(...)
  github.com/sagernet/sing-box/outbound/urltest.go:407

Goroutine 381 (the stuck batch worker):

goroutine 381 [IO wait, 1 minutes]:
net.(*TCPConn).Read(...)
  ...
github.com/sagernet/sing-box/common/urltest.URLTest(...)
  github.com/sagernet/sing-box/common/urltest/urltest.go:96
github.com/sagernet/sing-box/outbound.(*URLTestGroup).urlTest.func1()
  github.com/sagernet/sing-box/outbound/urltest.go:390
github.com/sagernet/sing/common/batch.(*Batch[...]).Go.func1()
  github.com/sagernet/sing@v0.5.1/common/batch/batch.go:59

Socket state at stall (from ss)

• 112 ESTAB connections with Send-Q = 0 (accepted but not writing)
• 5 CLOSE-WAIT with Recv-Q = 1 (remote sent FIN, sing-box never called close())
• conntrack: 76/76 ASSURED (TCP layer healthy, application layer dead)

Reproduction pattern

• Config: tproxy inbound, urltest outbound with 6 exit nodes via relay servers
• Traffic: normal residential (2-3 LAN devices, web browsing + streaming)
• Trigger: relay server becomes slow or unresponsive (accepts TCP, does not respond to HTTP)
• Stall occurs within 1-19 minutes of VPN reconnect during degraded relay conditions
• Restart of sing-box process restores function temporarily

Observed 8 stalls in 2 hours, with intervals shrinking: 13min, 19min, 6.5min, 57s, 4.5min, 11min, 5min, 4min

Root cause analysis

URLTestGroup.urlTest() at outbound/urltest.go:407 calls batch.Wait() which blocks on sync.WaitGroup.Wait(). The batch spawns one goroutine per outbound to run URL tests. If any single outbound's relay accepts the TCP connection but does not respond to the HTTP request, that batch worker blocks in Read() indefinitely. Since batch.Wait() requires ALL workers to complete, one stuck worker blocks the entire health check.

While the health check is blocked:

• selectedOutboundTCP/selectedOutboundUDP are never updated to healthy outbounds
• New connections continue routing to the unresponsive outbound
• Connection copy goroutines (2 per connection) accumulate in IO wait
• The gateway appears fully unresponsive to LAN devices

Suggested fix

Add a context timeout to the urltest batch, so that unresponsive outbounds are detected as failures rather than blocking the entire health check:

// outbound/urltest.go, in urlTest()
// Before: batch.Wait() blocks forever if one probe hangs
// After: timeout ensures batch completes even with unresponsive outbounds

ctx, cancel := context.WithTimeout(ctx, 30*time.Second)
defer cancel()
// Use ctx for batch operations so they respect the timeout

Or ensure individual URL test requests use a bounded timeout that covers the full HTTP transaction (connect + read), not just the TCP dial phase.

Deployment details

• Hardware: Intel N100 mini-PC, 8GB RAM
• Role: home network transparent proxy gateway
• Inbound: tproxy (TCP only, QUIC/UDP rejected)
• Outbound: urltest group selecting from 6 exit nodes (Dallas, LA, Chicago, NY, Atlanta, Miami) via relay servers
• BPF TCP keepalive: 30s (clamped via CGROUP_SETSOCKOPT)
• sysctl: tcp_retries2=6

Full goroutine dump and socket state

Captured by sending SIGQUIT to the sing-box process during a live stall event (GOTRACEBACK=all):

• Goroutine dump (588KB, 7256 lines, 205 goroutines): goroutine_dump.txt
• Socket state (ss -tnp, 117 connections, IPs sanitized): sockets_sanitized.txt

[HouMinXi]

Additional findings from more analysis (goroutine dump deep-dive)

After further analysis of the goroutine dump, three additional mechanisms were identified that compound the batch.Wait() block:

1. checking atomic flag suppresses all recovery

func (g *URLTestGroup) CheckOutbounds(...) {
    if g.checking.Swap(true) {
        return result, nil  // already checking, skip silently
    }
}

Once goroutine 103 is stuck in batch.Wait(), checking stays true permanently. All subsequent timer-triggered health checks (every 120s) return immediately without running. No error is logged. The system has no external signal that health checking has stopped. This is a third layer of the self-lock beyond the two Read() timeouts.

2. Goroutine age staircase confirms progressive accumulation

 10  IO wait, 4 min   -- early phase, system partially working
 18  IO wait, 2 min   -- mid phase
 26  IO wait, 1 min   -- acceleration
 66  IO wait, < 1 min -- final burst (6x the early rate)

The increasing count at younger ages is not goroutines exiting (they never exit due to missing read timeout). It reflects the traffic rate at each point: as relay stops forwarding, new blocked connections arrive faster. This is the rate signature of the self-locking loop.

3. Per-connection goroutine cost is 4, not 2

Each proxied connection consumes:

• 2x bufio.Copy goroutines (upload + download) in IO wait
• 1x task.Group.Run goroutine in select (waits for both copies)
• 1x CopyEarlyConn wrapper

112 ESTAB x ~4 goroutines = ~448 expected, but the dump shows 205 total because some connections share goroutines or have already partially completed. At dump time, the process has zero spare scheduling capacity. Even if user traffic stops, goroutines do not release (Read() blocks forever). The process is irrecoverable without kill.

4. context.WithTimeout is insufficient

Code review found that C.TCPTimeout (15s) is already set as a context timeout on URL test requests. However, context cancellation does not interrupt http.Client's Read phase when using a custom DialContext. The context deadline fires but the underlying TCP Read() continues blocking. The fix must use conn.SetReadDeadline() directly on the net.Conn.

Updated causal chain (triple self-lock)

relay stops forwarding (TCP alive, app-layer dead)
  |
  +--[layer 1] bufio.CopyConn Read() no idle timeout
  |            goroutines accumulate at 6x acceleration
  |
  +--[layer 2] urltest batch.Wait() no timeout
  |            selectedOutbound frozen on dead node
  |
  +--[layer 3] checking=true permanently
               all future health checks suppressed silently

Full analysis report and goroutine dump available in the gist linked above.

[HouMinXi]

Quick update: we patched our router with two fixes and ran it for a few hours. The situation is much better.

Before patching, the watchdog had to force-reconnect every few minutes because urltest froze. After patching, the proxy log shows an 18-minute gap with no errors between two relay trouble periods. That gap never existed before. At 17:08 urltest detected 2 dead outbounds, recovered, and traffic kept flowing through the remaining healthy ones. Only one reconnect in ~36 minutes, and that was the relay genuinely dead (direct probe 000, all connections gone), not a sing-box freeze.

The two patches (against v1.10.7):

Patch 1 — outbound/urltest.go: 30s timeout wrapping batch.Wait()

--- a/outbound/urltest.go
+++ b/outbound/urltest.go
@@ -363,8 +363,9 @@ func (g *URLTestGroup) urlTest(ctx context.Context, force bool) (map[string]uint
 	result := make(map[string]uint16)
 	if g.checking.Swap(true) {
 		return result, nil
 	}
 	defer g.checking.Store(false)
-	b, _ := batch.New(ctx, batch.WithConcurrencyNum[any](10))
+	b, batchCtx := batch.New(ctx, batch.WithConcurrencyNum[any](10))
 	checked := make(map[string]bool)
 	var resultAccess sync.Mutex
 	for _, detour := range g.outbounds {
@@ -385,7 +386,8 @@ func (g *URLTestGroup) urlTest(ctx context.Context, force bool) (map[string]uint
 		}
 		checked[realTag] = true
 		p, loaded := g.router.Outbound(realTag)
 		if !loaded {
 			continue
 		}
 		b.Go(realTag, func() (any, error) {
-			testCtx, cancel := context.WithTimeout(g.ctx, C.TCPTimeout)
+			testCtx, cancel := context.WithTimeout(batchCtx, C.TCPTimeout)
 			defer cancel()
 			t, err := urltest.URLTest(testCtx, g.link, p)
 			if err != nil {
@@ -404,7 +406,22 @@ func (g *URLTestGroup) urlTest(ctx context.Context, force bool) (map[string]uint
 			return nil, nil
 		})
 	}
-	b.Wait()
+	waitDone := make(chan struct{})
+	go func() {
+		b.Wait()
+		close(waitDone)
+	}()
+	timer := time.NewTimer(2 * C.TCPTimeout)
+	defer timer.Stop()
+	select {
+	case <-waitDone:
+	case <-timer.C:
+	}
 	g.performUpdateCheck()
 	return result, nil
 }

Patch 2 — common/urltest/urltest.go: SetReadDeadline on the probe connection

--- a/common/urltest/urltest.go
+++ b/common/urltest/urltest.go
@@ -94,6 +94,9 @@ func URLTest(ctx context.Context, link string, detour N.Dialer) (t uint16, err e
 	start := time.Now()
 	instance, err := detour.DialContext(ctx, "tcp", M.ParseSocksaddrHostPortStr(hostname, port))
 	if err != nil {
 		return
 	}
 	defer instance.Close()
+	instance.SetReadDeadline(time.Now().Add(C.TCPTimeout))
 	if earlyConn, isEarlyConn := common.Cast[N.EarlyConn](instance); isEarlyConn && earlyConn.NeedHandshake() {
 		start = time.Now()
 	}

Patch 2 is the primary fix. The root cause is that http.Client.Do() does not propagate context cancellation to net.Conn.Read() when the connection comes from a custom DialContext. The transport doesn't own the connection lifecycle, so Read() blocks forever on a dead relay even though the context has a 15s deadline. SetReadDeadline breaks that directly.

Patch 1 is a backup: if something else blocks inside a batch worker, the batch.Wait() timeout still lets the urltest cycle complete.

These are against v1.10.7. The master branch has urltest under protocol/group/urltest.go with some differences in initialization, but the same two changes apply conceptually.