Report MTU scan progress while the scan runs

internal/client/client.go

@@ -77,6 +77,9 @@ type Client struct {
 	resolverRuntimeLogMu     sync.Mutex
 	lastResolverRuntimeLog   string
 	lastResolverRuntimeLogAt time.Time
+	mtuProgressLogMu         sync.Mutex
+	lastMTUProgressPercent   int
+	lastMTUProgressAt        time.Time
 
 	// MTU States
 	mtuStateMu        sync.Mutex

internal/client/mtu.go

@@ -38,6 +38,12 @@ const (
 	// 1/8 = 12.5%) before the session adopts it, so flapping resolvers do not
 	// churn the session MTU. Stranded (unsustainable) points always move.
 	mtuHysteresisDivisor = 8
+	// The MTU scan owns the middle of the connect progress bar: it starts where
+	// the "starting" phase leaves off and stops below the "selecting" phase, so
+	// the bar only ever moves forward.
+	mtuProgressStartPercent = 10
+	mtuProgressSpanPercent  = 70
+	mtuProgressInterval     = 250 * time.Millisecond
 )
 
 var (
@@ -639,6 +645,9 @@ func (c *Client) runConnectionMTUTest(ctx context.Context, conn *Connection, ser
 	if conn == nil {
 		return
 	}
+	// Registered before the recover below so it runs after it: every exit path,
+	// panic included, has updated the counters by the time progress is reported.
+	defer c.logMTUProgress(counters, total)
 	defer func() {
 		if recovered := recover(); recovered != nil {
 			c.mtuStateMu.Lock()

internal/client/mtu_logging.go

@@ -49,6 +49,66 @@ func (c *Client) logConnectionProgress(phase string, percent int, keyValues ...a
 	c.log.Machinef("%s", b.String())
 }
 
+// logMTUProgress reports scan progress for the desktop app, which draws its
+// connection progress bar from these lines. The MTU scan is by far the longest
+// phase of a connect, so without it the bar sits at the "starting" percent and
+// then jumps straight to "selecting" when the scan ends.
+func (c *Client) logMTUProgress(counters *mtuScanCounters, total int) {
+	if counters == nil || total < 0 {
+		return
+	}
+	completed := int(counters.completed.Load())
+	valid := int(counters.valid.Load())
+	rejected := int(counters.rejectUpload.Load() + counters.rejectDownload.Load())
+	percent := mtuProgressStartPercent
+	if total > 0 {
+		percent += (mtuProgressSpanPercent * completed) / total
+	}
+	if !c.shouldLogMTUProgress(completed, total, percent) {
+		return
+	}
+	c.logConnectionProgress(
+		"mtu",
+		percent,
+		"completed", completed,
+		"total", total,
+		"valid", valid,
+		"rejected", rejected,
+	)
+}
+
+func (c *Client) resetMTUProgressThrottle() {
+	if c == nil {
+		return
+	}
+	c.mtuProgressLogMu.Lock()
+	c.lastMTUProgressPercent = -1
+	c.lastMTUProgressAt = time.Time{}
+	c.mtuProgressLogMu.Unlock()
+}
+
+// shouldLogMTUProgress holds the machine output to one line per percent step,
+// and never drops the first or last line of a scan.
+func (c *Client) shouldLogMTUProgress(completed, total, percent int) bool {
+	if c == nil {
+		return true
+	}
+	now := c.now()
+	c.mtuProgressLogMu.Lock()
+	defer c.mtuProgressLogMu.Unlock()
+	if completed == 0 || (total > 0 && completed >= total) {
+		c.lastMTUProgressPercent = percent
+		c.lastMTUProgressAt = now
+		return true
+	}
+	if c.lastMTUProgressPercent != percent || c.lastMTUProgressAt.IsZero() || now.Sub(c.lastMTUProgressAt) >= mtuProgressInterval {
+		c.lastMTUProgressPercent = percent
+		c.lastMTUProgressAt = now
+		return true
+	}
+	return false
+}
+
 func (c *Client) logMTUProbe(isRetry bool, background bool, format string, args ...any) {
 	if isRetry || background || !c.mtuDebugEnabled() {
 		return
@@ -57,6 +117,7 @@ func (c *Client) logMTUProbe(isRetry bool, background bool, format string, args
 }
 
 func (c *Client) logMTUStart(workerCount int) {
+	c.resetMTUProgressThrottle()
 	if !c.mtuInfoEnabled() {
 		return
 	}

internal/client/mtu_progress_test.go

@@ -0,0 +1,80 @@
+package client
+
+import (
+	"path/filepath"
+	"strings"
+	"testing"
+	"time"
+
+	"cottendns-go/internal/logger"
+)
+
+// The desktop app draws its connection progress bar from WD_PROGRESS lines, so
+// the MTU scan has to report as it goes. It must survive LOG_LEVEL=WARN, which
+// suppresses the human-readable per-resolver lines.
+func TestLogMTUProgressEmitsMachineLinesAtWarn(t *testing.T) {
+	path := filepath.Join(t.TempDir(), "log.txt")
+	log := logger.NewWithFile("test", "WARN", path)
+	t.Cleanup(func() { _ = log.Close() })
+
+	now := time.Now()
+	c := &Client{log: log, nowFn: func() time.Time { return now }}
+	c.resetMTUProgressThrottle()
+
+	counters := &mtuScanCounters{}
+	total := 4
+
+	c.logMTUProgress(counters, total) // completed=0, always emitted
+	for i := 0; i < total; i++ {
+		counters.completed.Add(1)
+		if i%2 == 0 {
+			counters.valid.Add(1)
+		} else {
+			counters.rejectUpload.Add(1)
+		}
+		now = now.Add(mtuProgressInterval)
+		c.logMTUProgress(counters, total)
+	}
+
+	out := readFile(t, path)
+	for _, want := range []string{
+		"WD_PROGRESS phase=mtu percent=10 completed=0 total=4",
+		"WD_PROGRESS phase=mtu percent=27 completed=1 total=4 valid=1 rejected=0",
+		"WD_PROGRESS phase=mtu percent=80 completed=4 total=4 valid=2 rejected=2",
+	} {
+		if !strings.Contains(out, want) {
+			t.Fatalf("missing %q in:\n%s", want, out)
+		}
+	}
+}
+
+// The scan runs one probe per resolver-domain pair and they finish in bursts, so
+// unthrottled reporting would flood the log. Repeats within the interval that do
+// not move the percent are dropped, but the final line never is.
+func TestLogMTUProgressThrottlesRepeats(t *testing.T) {
+	path := filepath.Join(t.TempDir(), "log.txt")
+	log := logger.NewWithFile("test", "WARN", path)
+	t.Cleanup(func() { _ = log.Close() })
+
+	now := time.Now()
+	c := &Client{log: log, nowFn: func() time.Time { return now }}
+	c.resetMTUProgressThrottle()
+
+	counters := &mtuScanCounters{}
+	counters.completed.Store(1)
+	total := 100
+
+	c.logMTUProgress(counters, total)
+	c.logMTUProgress(counters, total)
+	c.logMTUProgress(counters, total)
+
+	if got := strings.Count(readFile(t, path), "phase=mtu"); got != 1 {
+		t.Fatalf("expected the repeats to be throttled to one line, got %d", got)
+	}
+
+	counters.completed.Store(int32(total))
+	c.logMTUProgress(counters, total)
+	if !strings.Contains(readFile(t, path), "completed=100 total=100") {
+		t.Fatal("the final progress line must never be throttled away")
+	}
+}