diff --git a/internal/client/client.go b/internal/client/client.go index e3b9ebd..87e3330 100644 --- a/internal/client/client.go +++ b/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 diff --git a/internal/client/mtu.go b/internal/client/mtu.go index d5f90a9..774bb86 100644 --- a/internal/client/mtu.go +++ b/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() diff --git a/internal/client/mtu_logging.go b/internal/client/mtu_logging.go index 8f42676..ae96339 100644 --- a/internal/client/mtu_logging.go +++ b/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 } diff --git a/internal/client/mtu_progress_test.go b/internal/client/mtu_progress_test.go new file mode 100644 index 0000000..50608e9 --- /dev/null +++ b/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") + } +}